如何在 sharedPreferences 中分析 ANR
How to analyze ANR in sharedPreferences
sharedPreferences遇到ANR，不知道怎么定位问题。
这里是trace的三个部分，其他的帖子大多是"WAIT"或者"TIMED_WAIT"。 "main" 线程因 countdownlatch.await() 而被阻塞。
第二个线程 "pool-1-thread-1" 等待 fsync。
最后一个正在尝试阅读一些东西。
我认为 2nd 线程阻塞了主线程，因为如果这个不能完成，它不会调用 countdownlatch.countdown()，所以主线程必须等待。
但我不明白为什么它会在 fsync 中停止。第 3 个线程与此相关吗？
线程 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.run(SharedPreferencesImpl.java:364)
at android.app.QueuedWork.waitToFinish(QueuedWork.java:88)
at android.app.ActivityThread.handleServiceArgs(ActivityThread.java:2697)
at android.app.ActivityThread.access00(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.access0(SharedPreferencesImpl.java:52)
at android.app.SharedPreferencesImpl.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)
我知道发生了什么事了。
从三个轨迹可以看出：
- 共享首选项被文件同步阻止。
- fsync 正在等待某些东西（应该是磁盘）。
- 一个线程正在做磁盘操作。
仔细查看源码发现，很多SP的get/set都是用来记录应用启动时的状态的。与此同时，有一个新线程试图从服务器下载大数据，如 .jar 或 .so 。
对于一些旧设备，下载大数据可能会发生大量 GC 并且 "apache" lib 尝试通过 "Wire" 记录所有内容。所以，有时候，它会花费太长时间并导致 SP 超时。
修复是
- 关闭 Apache 日志
- 将状态保存在内存中并将它们设置为一个对象。
- 从初始化部分移除一些背景行为。
这是由于 Android 的 SharedPreferences 实现中存在的错误：
目前，任何使用 SharedPreferences.Editor.apply() 都像是为 ANR 安排了一颗定时炸弹。
sharedPreferences遇到ANR，不知道怎么定位问题。
这里是trace的三个部分，其他的帖子大多是"WAIT"或者"TIMED_WAIT"。 "main" 线程因 countdownlatch.await() 而被阻塞。 第二个线程 "pool-1-thread-1" 等待 fsync。 最后一个正在尝试阅读一些东西。
我认为 2nd 线程阻塞了主线程，因为如果这个不能完成，它不会调用 countdownlatch.countdown()，所以主线程必须等待。
但我不明白为什么它会在 fsync 中停止。第 3 个线程与此相关吗？
线程 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.run(SharedPreferencesImpl.java:364)
at android.app.QueuedWork.waitToFinish(QueuedWork.java:88)
at android.app.ActivityThread.handleServiceArgs(ActivityThread.java:2697)
at android.app.ActivityThread.access00(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.access0(SharedPreferencesImpl.java:52)
at android.app.SharedPreferencesImpl.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)
我知道发生了什么事了。
从三个轨迹可以看出：
- 共享首选项被文件同步阻止。
- fsync 正在等待某些东西（应该是磁盘）。
- 一个线程正在做磁盘操作。
仔细查看源码发现，很多SP的get/set都是用来记录应用启动时的状态的。与此同时，有一个新线程试图从服务器下载大数据，如 .jar 或 .so 。 对于一些旧设备，下载大数据可能会发生大量 GC 并且 "apache" lib 尝试通过 "Wire" 记录所有内容。所以，有时候，它会花费太长时间并导致 SP 超时。
修复是
- 关闭 Apache 日志
- 将状态保存在内存中并将它们设置为一个对象。
- 从初始化部分移除一些背景行为。
这是由于 Android 的 SharedPreferences 实现中存在的错误：
目前，任何使用 SharedPreferences.Editor.apply() 都像是为 ANR 安排了一颗定时炸弹。