How to get something useful from this ANR log

Question

I'm struggling with ANRs for a few weeks now but I still feel blind with logs like this. It is too long for stackoverflow and I have no idea which part might be useful. It happens usually during initial synchronization when there is a ton of network request being processed in the background (and I'm almost 100% sure non of that is in the main thread) and I'm also making a lot of UI stuff like populating recyclerviews from shared preferences via RxJava observables so I'm observing a massive changes in SharedPreferences and using sample method to handle possible back pressure. Thanks for any tips, I'm totally lost.

Answer 1

You have thread dumps for multiple processes in there. To get to the useful part, you can search for "Cmd line" until you find your process ("cz.vcelka.androidapp", the pid was 21574).

If you get an ANR that means that your main thread is blocked somehow, so you should look at its stack trace. Here it is :

"main" prio=5 tid=1 Waiting
  | group="main" sCount=1 dsCount=0 obj=0x74bc2fa0 self=0xb4db6500
  | sysTid=21574 nice=0 cgrp=default sched=0/0 handle=0xb6fc1b34
  | state=S schedstat=( 0 0 0 ) utm=785 stm=88 core=1 HZ=100
  | stack=0xbe29a000-0xbe29c000 stackSize=8MB
  | held mutexes=
  at java.lang.Object.wait!(Native method)
  - waiting on <0x05853836> (a java.lang.Object)
  at java.lang.Thread.parkFor$(Thread.java:1220)
  - locked <0x05853836> (a java.lang.Object)
  at sun.misc.Unsafe.park(Unsafe.java:299)
  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:810)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:971)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1278)
  at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:203)
  at android.app.SharedPreferencesImpl$EditorImpl$1.run(SharedPreferencesImpl.java:366)
  at android.app.QueuedWork.waitToFinish(QueuedWork.java:88)
  at android.app.ActivityThread.handleStopActivity(ActivityThread.java:3560)
  at android.app.ActivityThread.-wrap20(ActivityThread.java:-1)
  at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1373)
  at android.os.Handler.dispatchMessage(Handler.java:102)
  at android.os.Looper.loop(Looper.java:148)
  at android.app.ActivityThread.main(ActivityThread.java:5417)
  at java.lang.reflect.Method.invoke!(Native method)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:726)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:616)

So your main thread is blocked waiting on a CountDownLatch inside SharedPreferences code. We can look at the source code of SharedPreferences to find out more. At some point when you called SharedPreferences.Editor.apply(), the SharedPreferences code enqueued the write to disk to a worker thread. It also called QueuedWork.add(awaitCommit), where awaitCommit is a Runnable that waits on the write operation (by means of CountDownLatch), and QueuedWork.add() is a method that enqueues work to be done on the main thread when the activity's onPause method is called. That is what happened : onPause was called, and now the main thread is stuck waiting on the worker thread to complete its write operation.

Now the problem is that the log you posted is incomplete. Several threads are missing, including the worker thread that never called CountDownLatch.countDown(), so it is not possible to tell what is causing the deadlock. If you post the whole log (for your process, I don't think the other ones are going to be useful), we can probably help more.

Edit : I noticed that someone else here ran into the same problem. For them, the worker thread was stuck in fsync(2). fsync can be really slow (as in multiple seconds) if the file is big and / or the disk is busy. I suppose that could be causing the ANR. I'm not sure if that would classify as a bug in SharedPreferences... Seems a bit weird to trigger possibly long blocking operations on the main thread, even if called from onPause... If this is indeed your problem, the only workaround I can think of would be to use commit() instead of apply(), since that will do the write synchronously. You should do it from a background thread, given that in your particular setup it seems that it can take a pretty long time to flush to disk !

Or maybe your SharedPreferences file is just way too big, in which case you could try slimming it down (by using a database for instance).