9

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.

Rick Sanchez
  • 4,528
  • 2
  • 27
  • 53
  • Would it make sense to move the part you really need to debug to an AsyncTask, just for the sake of debugging it? Or alternatively, separating code parts and executing them in order using Handler.post(Runnable), just so the main thread can take a breath in between? (you'll have to set multiple breakpoints in this scenario) – SirKnigget May 07 '17 at 14:07
  • @SirKnigget Yes, that's a workaround I've thought of, and used some times. I'm looking for a more permanent solution. – Rick Sanchez May 07 '17 at 17:30
  • Did you try to use `android.os.Debug.waitForDebugger()` and insert a break-point after that? – Haris Qurashi May 09 '17 at 13:52
  • @HarisQureshi No change. Still crashes the app. – Rick Sanchez May 10 '17 at 01:35
  • can you depict MainActivity.java (com.kushtrim.playground/.MainActivity) here. – Radhey May 11 '17 at 05:02
  • 1
    I had the same issue in the Windows Subsystem for Android on Windows 11. The method described in the top answer with `adb shell am set-debug-app --persistent` resolved the issue. – Attila Tanyi Jan 31 '23 at 13:19

4 Answers4

13

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.

Rick Sanchez
  • 4,528
  • 2
  • 27
  • 53
5

ANRs can be triggered by holding the main thread as a new event comes in on the main thread. This event may be an input or as simple as a BroadcastReceiver picking up an Intent.

This is important to note because your app may be doing another task in the main thread at the same time you are trying to debug.

Directly from the documentation on ANRs:

This means anything your application is doing in the UI thread that takes a long time to complete can trigger the ANR dialog because your application is not giving itself a chance to handle the input event or intent broadcasts.

You can trace down what other piece of code is running on the main thread or you can attempt the more daring solution below.

Since you mentioned that you can modify the AOSP and this is only for debugging you could try an epic hack that will let you debug.

The ANR timeout time is defined in file InputDispatcher.cpp in the /frameworks/base/libs/ui path. 

const nsecs_t DEFAULT_INPUT_DISPATCHING_TIMEOUT = 5000 * 1000000LL;

Nothing stops you from changing that value so that you can debug in peace!

Newtron Labs
  • 809
  • 1
  • 5
  • 17
  • Thank you. I had the same idea a while back, but couldn't find the constant to modify. I like this, but nevertheless this is the nuclear option for now. Let's see if there is a way to keep this at the normal value, and fix it just for the debugger, because then I would not see the normal ANR that could happen. – Rick Sanchez May 05 '17 at 03:58
  • Also, would like to add something. I found that it isn't the app's fault, but something with OS. I was able to reproduce the crash by creating a brand new project, adding a button and an OnClickListener for it and then putting a breakpoint in it. – Rick Sanchez May 05 '17 at 04:08
  • @RickSanchez Very interesting. I agree worse case scenario you go for the "nuclear" option and continue your original work. – Newtron Labs May 05 '17 at 05:32
  • I solved the issue in another way, but I don't want to let the bounty go to waste, so I'm awarding it to you ( you were the first to answer, and I like creative solution ) – Rick Sanchez May 11 '17 at 08:38
  • @RickSanchez Thank you Rick, much appreciated. Glad you were able to solve your issue! – Newtron Labs May 11 '17 at 17:48
  • Hey guys, thanks for your answers. Do you know where is InputDispatcher.cpp stored please ? Where can I find /frameworks/base/libs/ui ? thanks ! – clst Jun 01 '20 at 15:22
2

I would try something like the following - I don't have your problematic device so I can't test it myself.

In ActivityManagerService.java (the part which displays the ANR dialog): http://androidxref.com/4.4.4_r1/xref/frameworks/base/services/java/com/android/server/am/ActivityManagerService.java#1124

Add a condition:

if (proc != null && proc.debugging) {      
     return;
}

I don't know which Android version you're building, so there might be slight differences than the linked file of course.

SirKnigget
  • 3,614
  • 2
  • 28
  • 61
  • Thanks, I'll try this. As I saw, this is the last part of the ANR showing flow, which actually shows the ANR. Would it make sense to add the check earlier. Inspired by this, I found a method named notifyANR in InputMonitor.java . – Rick Sanchez May 07 '17 at 17:34
  • Whatever, as long as it does the job... I guess that what interrupts the debugging flow is just the dialog, right? Does it matter if the system is screaming in logcat but you can still debug? – SirKnigget May 08 '17 at 02:34
  • No, what stops the debugging is the system killing the app. That's why I asked whether we should check somewhere earlier? I'm worried that maybe the system does something to stop things before the place you mentioned. – Rick Sanchez May 08 '17 at 03:26
  • Ok, for some reason I thought that the dialog is what annoys you. What about this code part: killAppAtUsersRequest(proc, null); (At the end of the function), isn't this the part that kills the process? Anyway, even when the dialog is shown, isn't there a "wait" option? – SirKnigget May 08 '17 at 07:51
  • The dialog doesn't get shown at all. The OS just kills my app. – Rick Sanchez May 08 '17 at 07:56
  • That's bizzarre. Is this a normal AOSP tag that you're building? Are the contents of ActivityManagerService.java in your code base similar to what I looked at? Anyway, try removing killAppAtUsersRequest(proc, null)... – SirKnigget May 08 '17 at 08:25
1

Well, I made some checks. I noticed that using a Nexus 5x with the debugger attached and putting a break point in the onClick method does not launch ANR.

If I detach the debugger the ANR is launched as expected.

So, that's why I guess the SO is taking account of the debugger being attached and ignoring (or avoiding to launch) the ANR dialog.

I guess you are using a SO slightly different to the ones used in smartphones (maybe an old version?), but here some considerations.

  1. The ANR is shown when Main Thread is blocked by a long running task, or any other reason. It makes sense the debugger produces an ANR because debugger stops the thread.

  2. The thread that checks that main thread is blocked can't be the main thread.

  3. To avoid ANR it is necessary to communicate the component that checks if Main Thread is blocked that we are on debug mode. Probably using another version of the SO solves this problem for you.

  4. Or maybe block all the threads running in the system.

The answer of @CJBS could be useful for you:

Android Studio threaded debugging

Break Points in android Studio can be configured to suspend all running threads. That's should be enough to avoid ANR.

Community
  • 1
  • 1
jDur
  • 1,481
  • 9
  • 10