How to debug an ANR

Question

I'm having trouble debugging my application. It is a data collection application and each "job" takes around 15 minutes to complete, where multiple jobs being completed in quick succession is a normal use case.

The symptoms I see are as follows:

After the application has been running for between 20 and 90 minutes the application displays an ANR message. I say between 20 and 90 because the timing at which the ANR appears is variable; sometimes it pops up during the second job, sometimes you can get to job 8 before it pops up.

Once the ANR has come up I choose "wait" and the dialog is dismissed so I continue with the job... Now every 5 minutes (without fail!) the ANR keeps reappearing. Every time I choose "wait", 5 minutes later it comes back.

There are no postDelayed or AlarmManager or TimerTask in my application that fire on a 5 minute schedule. And the ANR message specifically says "SHADE isn't responding", my app is called SHADE so Android certainly thinks that it is my app that is causing the problem.

I've followed the advice for turning on StrictMode but to no avail, the logs dont have any StrictMode violations anywhere near the time of the ANR.

10-16 17:11:28.390 D/StrictMode(29898): StrictMode policy violation; ~duration=8 ms: android.os.StrictMode$StrictModeDiskWriteViolation: policy=2335 violation=1
10-16 17:14:09.180 D/CrashAnrDetector(  869): Subject: Executing service com.ancoris.shade/.ShadeService
10-16 17:19:22.560 D/CrashAnrDetector(  869): Subject: Executing service com.ancoris.shade/.ShadeService
10-16 17:24:30.010 D/CrashAnrDetector(  869): Subject: Executing service com.ancoris.shade/.ShadeService
10-16 17:29:39.860 D/CrashAnrDetector(  869): Subject: Executing service com.ancoris.shade/.ShadeService
10-16 17:34:46.860 D/CrashAnrDetector(  869): Subject: Executing service com.ancoris.shade/.ShadeService

The last violation happens way before the ANR. And I'm not sure how else to determine what is causing the ANR to happen.

I have only been able to replicate the issue on our targeted device: Samsung Galaxy Tab Active 4 16GB

samsung/rubensltexx/rubenslte:4.4.4/KTU84P/T365XXU1AOA3:user/release-keys

The issue does not occur on a Nexus 7 or Nexus 9 (both running 5.1.1).

Update: Ok, so I've used DDMS to get a method profile, the below file was captured over a ~10 minute period, where a ANR message is displayed half way through and then again at the end, both times I pressed "wait" on the message.

The profile doesn't appear to mention any of my com.ancoris.shade files or methods at all.

https://drive.google.com/file/d/0B8JuL0rVSQEKZUJPYmFIR3dDMkE/view?usp=sharing

Update 2:

I've just seen this in one of the logs (data/anr/traces.tx). Is this normal or is this the cause of my issue? If it is, how should I debug something like this when my code isn't even mentioned in the Stack Trace?

"main" prio=5 tid=1 SUSPENDED
  | group="main" sCount=1 dsCount=0 obj=0x4188cea0 self=0x4177c008
  | sysTid=16094 nice=0 sched=0/0 cgrp=apps handle=1074479444
  | state=S schedstat=( 0 0 0 ) utm=8522 stm=1572 core=0
  at android.widget.TextView.restartMarqueeIfNeeded(TextView.java:~5762)
  at android.widget.TextView.onDraw(TextView.java:6474)
  at android.view.View.draw(View.java:15551)
  at android.view.View.draw(View.java:15436)
  at android.view.ViewGroup.drawChild(ViewGroup.java:3366)
  at android.view.ViewGroup.dispatchDraw(ViewGroup.java:3202)
  at android.view.View.draw(View.java:15434)
  at android.view.ViewGroup.drawChild(ViewGroup.java:3366)
  at android.view.ViewGroup.dispatchDraw(ViewGroup.java:3202)
  at android.view.View.draw(View.java:15434)
  at android.view.ViewGroup.drawChild(ViewGroup.java:3366)
  at android.view.ViewGroup.dispatchDraw(ViewGroup.java:3202)
  at android.view.View.draw(View.java:15554)
  at android.widget.FrameLayout.draw(FrameLayout.java:472)
  at android.widget.ScrollView.draw(ScrollView.java:2418)
  at android.view.View.draw(View.java:15436)
  at android.view.ViewGroup.drawChild(ViewGroup.java:3366)
  at android.view.ViewGroup.dispatchDraw(ViewGroup.java:3202)
  at android.view.View.draw(View.java:15434)
  at android.view.ViewGroup.drawChild(ViewGroup.java:3366)
  at android.view.ViewGroup.dispatchDraw(ViewGroup.java:3202)
  at android.view.View.draw(View.java:15434)
  at android.view.ViewGroup.drawChild(ViewGroup.java:3366)
  at android.view.ViewGroup.dispatchDraw(ViewGroup.java:3202)
  at android.view.View.draw(View.java:15434)
  at android.view.ViewGroup.drawChild(ViewGroup.java:3366)
  at android.view.ViewGroup.dispatchDraw(ViewGroup.java:3202)
  at android.view.View.draw(View.java:15434)
  at android.view.ViewGroup.drawChild(ViewGroup.java:3366)
  at android.view.ViewGroup.dispatchDraw(ViewGroup.java:3202)
  at android.view.View.draw(View.java:15434)
  at android.view.ViewGroup.drawChild(ViewGroup.java:3366)
  at android.view.ViewGroup.dispatchDraw(ViewGroup.java:3202)
  at android.view.View.draw(View.java:15434)
  at android.view.ViewGroup.drawChild(ViewGroup.java:3366)
  at android.view.ViewGroup.dispatchDraw(ViewGroup.java:3202)
  at android.view.View.draw(View.java:15434)
  at android.view.ViewGroup.drawChild(ViewGroup.java:3366)
  at android.view.ViewGroup.dispatchDraw(ViewGroup.java:3202)
  at android.view.View.draw(View.java:15554)
  at com.android.internal.widget.ActionBarOverlayLayout.draw(ActionBarOverlayLayout.java:471)
  at android.view.View.draw(View.java:15436)
  at android.view.ViewGroup.drawChild(ViewGroup.java:3366)
  at android.view.ViewGroup.dispatchDraw(ViewGroup.java:3202)
  at android.view.View.draw(View.java:15554)
  at android.widget.FrameLayout.draw(FrameLayout.java:472)
  at com.android.internal.policy.impl.PhoneWindow$DecorView.draw(PhoneWindow.java:2623)
  at android.view.ViewRootImpl.drawSoftware(ViewRootImpl.java:2956)
  at android.view.ViewRootImpl.draw(ViewRootImpl.java:2869)
  at android.view.ViewRootImpl.performDraw(ViewRootImpl.java:2707)
  at android.view.ViewRootImpl.performTraversals(ViewRootImpl.java:2275)
  at android.view.ViewRootImpl.doTraversal(ViewRootImpl.java:1297)
  at android.view.ViewRootImpl$TraversalRunnable.run(ViewRootImpl.java:6775)
  at android.view.Choreographer$CallbackRecord.run(Choreographer.java:813)
  at android.view.Choreographer.doCallbacks(Choreographer.java:613)
  at android.view.Choreographer.doFrame(Choreographer.java:583)
  at android.view.Choreographer$FrameDisplayEventReceiver.run(Choreographer.java:799)
  at android.os.Handler.handleCallback(Handler.java:733)
  at android.os.Handler.dispatchMessage(Handler.java:95)
  at android.os.Looper.loop(Looper.java:146)
  at android.app.ActivityThread.main(ActivityThread.java:5756)
  at java.lang.reflect.Method.invokeNative(Native Method)
  at java.lang.reflect.Method.invoke(Method.java:515)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:1291)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1107)
  at dalvik.system.NativeStart.main(Native Method)

Answer 1

Profiling is done by adding 2 method calls to somewhere in your application, a .trace file is generated when you run your app with profiling.

Code to add: Debug.startMethodTracing("profileName");//put where you want to start profiling ie. application.onCreate

Debug.stopMethodTracing(); //put this where you want the trace to end

Run your app (it will run considerably slower while profile.

After app has gotten past the point where you stopped profile go to terminal and run

adb pull /sdcard/profileName.trace

Open Android Device Monitor (in Studio:tools->Android->Android Device Monitor)

File open the trace

Observe the trace, clicking on a row will allow you to drill down into children calls which will help identify slowdowns.