如何分析 sharedPreferences 中的 ANR

Question

在sharedPreferences中遇到一个ANR，不知道怎么定位问题。

这里是来自trace的三个部分，大多数其他线程是“WAIT”或“TIMED_WAIT”。由于 countdownlatch.await()，“主”线程被阻塞。 第二个线程“pool-1-thread-1”等待 fsync。 最后一个正在尝试读取内容。

我认为第二个线程已经阻塞了主线程，因为如果这个不能完成，它不会调用 countdownlatch.countdown()，所以主线程必须等待。

但我不知道为什么它会在 fsync 中停止。第三条跟这个有关系吗？

线程1

"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)

线程2

"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)

线程3

"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

我已经弄清楚发生了什么。

从三个痕迹中，我们可以看出：
- 共享首选项被文件同步阻止。
- fsync 正在等待某些东西（应该是磁盘）。
- 一个线程正在做磁盘操作。

我仔细查看源码后发现，很多SP的get/set都是用来记录app启动时的状态的。同时，有一个新线程试图从服务器下载大数据，如 .jar 或 .so 。 对于一些旧设备，下载大数据可能会发生繁重的 GC 和“apache”库尝试通过“Wire”记录所有内容。因此，有时，它会花费太长时间并导致 SP 超时。

解决方法是
- 关闭 apache 日志
- 将状态保存在内存中并将它们一起设置为一个对象。
- 从初始化部分移动一些背景行为。

Answer 2

这是由于 Android 的 SharedPreferences 实现中的一个现有错误：

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

目前，对SharedPreferences.Editor.apply() 的任何使用都像是为 ANR 安排了一个定时炸弹。