How to analyze ANR in sharedPreferences

Question

Meet a ANR in sharedPreferences, don't know how to locate the problem.

Here are three parts from trace, most of other threads are "WAIT" or "TIMED_WAIT". "main" thread is blocked because of countdownlatch.await(). 2nd thread "pool-1-thread-1" waiting for the fsync. The last one is trying to read something.

I think 2nd thread has blocked main thread, because if this one can't finish, it won't invoke countdownlatch.countdown(), so the main thread have to wait.

But I can't figure out why it stops in the fsync. Is the 3rd thread related to this?

thread1

"main" prio=5 tid=1 WAIT
| group="main" sCount=1 dsCount=0 obj=0x418efe58 self=0x4180b6e8
| sysTid=4178 nice=-6 sched=0/0 cgrp=apps handle=1074565460
| state=S schedstat=( 3385090416 1929697750 7848 ) utm=278 stm=60 core=3
at java.lang.Object.wait(Native Method)
- waiting on <0x418eff28> (a java.lang.VMThread) held by tid=1 (main)
at java.lang.Thread.parkFor(Thread.java:1205)
at sun.misc.Unsafe.park(Unsafe.java:325)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:157)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:813)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:973)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1281)
at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:202)
at android.app.SharedPreferencesImpl$EditorImpl$1.run(SharedPreferencesImpl.java:364)
at android.app.QueuedWork.waitToFinish(QueuedWork.java:88)
at android.app.ActivityThread.handleServiceArgs(ActivityThread.java:2697)
at android.app.ActivityThread.access$2100(ActivityThread.java:138)
at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1296)
at android.os.Handler.dispatchMessage(Handler.java:102)
at android.os.Looper.loop(Looper.java:136)
at android.app.ActivityThread.main(ActivityThread.java:5095)
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:786)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:602)

thread2

"pool-1-thread-1" prio=5 tid=10 SUSPENDED
| group="main" sCount=1 dsCount=0 obj=0x41ca62e0 self=0x6034b008
| sysTid=4246 nice=0 sched=0/0 cgrp=apps handle=1612996584
| state=S schedstat=( 189967314 218846863 555 ) utm=15 stm=3 core=2
#00  pc 00021af0  /system/lib/libc.so (__futex_syscall3+8)
#01  pc 0000f0b4  /system/lib/libc.so (__pthread_cond_timedwait_relative+48)
#02  pc 0000f114  /system/lib/libc.so (__pthread_cond_timedwait+64)
#03  pc 000566e7  /system/lib/libdvm.so
#04  pc 00056ca9  /system/lib/libdvm.so (dvmChangeStatus(Thread*, ThreadStatus)+34)
#05  pc 0005115f  /system/lib/libdvm.so (dvmCallJNIMethod(unsigned int const*, JValue*, Method const*, Thread*)+406)
#06  pc 00029960  /system/lib/libdvm.so
#07  pc 00030dec  /system/lib/libdvm.so (dvmMterpStd(Thread*)+76)
#08  pc 0002e484  /system/lib/libdvm.so (dvmInterpret(Thread*, Method const*, JValue*)+184)
#09  pc 000635b9  /system/lib/libdvm.so (dvmCallMethodV(Thread*, Method const*, Object*, bool, JValue*, std::__va_list)+336)
#10  pc 000635dd  /system/lib/libdvm.so (dvmCallMethod(Thread*, Method const*, Object*, JValue*, ...)+20)
#11  pc 000582bb  /system/lib/libdvm.so
#12  pc 0000d2c0  /system/lib/libc.so (__thread_entry+72)
#13  pc 0000d458  /system/lib/libc.so (pthread_create+240)
at libcore.io.Posix.fsync(Native Method)
at libcore.io.BlockGuardOs.fsync(BlockGuardOs.java:97)
at java.io.FileDescriptor.sync(FileDescriptor.java:74)
at android.os.FileUtils.sync(FileUtils.java:154)
at android.app.SharedPreferencesImpl.writeToFile(SharedPreferencesImpl.java:597)
at android.app.SharedPreferencesImpl.access$800(SharedPreferencesImpl.java:52)
at android.app.SharedPreferencesImpl$2.run(SharedPreferencesImpl.java:511)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
at java.lang.Thread.run(Thread.java:841)

thread3

"Thread-5346" prio=5 tid=48 SUSPENDED
| group="main" sCount=1 dsCount=0 obj=0x42b9e3c0 self=0x6278f280
| sysTid=4841 nice=0 sched=0/0 cgrp=apps handle=1652085768
| state=S schedstat=( 6396036717 2412660825 15121 ) utm=612 stm=27 core=1
at java.lang.StackTraceElement.<init>(StackTraceElement.java:~61)
at java.lang.Throwable.nativeGetStackTrace(Native Method)
at java.lang.Throwable.getInternalStackTrace(Throwable.java:264)
at java.lang.Throwable.getStackTrace(Throwable.java:200)
at org.apache.commons.logging.impl.Jdk14Logger.log(Jdk14Logger.java:88)
at org.apache.commons.logging.impl.Jdk14Logger.debug(Jdk14Logger.java:113)
at org.apache.http.impl.conn.Wire.wire(Wire.java:64)
at org.apache.http.impl.conn.Wire.input(Wire.java:116)
at org.apache.http.impl.conn.LoggingSessionInputBuffer.read(LoggingSessionInputBuffer.java:74)
at org.apache.http.impl.io.ContentLengthInputStream.read(ContentLengthInputStream.java:174)
at org.apache.http.conn.EofSensorInputStream.read(EofSensorInputStream.java:159)
at org.qiyi.android.coreplayer.a.aux.a(SourceFile:206)
at org.qiyi.android.coreplayer.a.aux.a(SourceFile:140)
at org.qiyi.android.coreplayer.a.aux.a(SourceFile:105)
at org.qiyi.android.coreplayer.a.com7.a(SourceFile:361)
at org.qiyi.android.coreplayer.a.nul.run(SourceFile:158)
at java.lang.Thread.run(Thread.java:841)

Answer 1

This is due to an existing bug in Android's implementation of SharedPreferences:

https://issuetracker.google.com/issues/117796731

Currently, any use of SharedPreferences.Editor.apply() is like scheduling a time bomb for ANR.

Answer 2

I've figure out what happening.

from three traces, we can see that:
- the shared preferences is blocked by a file sync.
- the fsync is waiting for something(should be disk).
- a thread is doing the disk operation.

After I check the source codes carefully, lots of SP's get/set are used to record states when the app is launched. Mean while, there is a new thread trying to download big data from sever, like .jar or .so . For some old devices, downloading big datas can occur heavy GC and "apache" lib try to log everything by "Wire". So, sometime, it just takes too long and cause the SP time out.

The fix is
- turn off the apache log
- save state in memory and set them together as one object.
- move some background behavior from the initialize part.