16

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)
mjgrrrr
  • 241
  • 2
  • 13
  • 3
    Please post your code also. So we can understand the question well? – Tharindu Welagedara Apr 28 '16 at 04:44
  • 1
    In fact, it is a big project and I can't tell which part of codes occur this... SharedPreferences are used in too many places. – mjgrrrr Apr 28 '16 at 10:25
  • 3
    Hello, I just noticed your question, it seems that you have the same problem as in this question : stackoverflow.com/q/37549578. I have attempted to answer the other question but I'm not certain what's to be done. In short, an `onPause` call triggered the wait on the main thread from the `SharedPreferences` code. Not sure if that is a bug in `SharedPreferences` or not. You could try using `commit()` from a background thread instead of `apply()`. Or you could reduce the size of your `SharedPreferences` file, to see if it syncs faster. – Samuel Peter May 31 '16 at 16:56
  • Do you still see this issue? Is it because you use "commit" instead of "apply"? Or just reading from the SharedPreferences? – android developer Nov 25 '19 at 15:05

2 Answers2

9

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.

Hanson Char
  • 230
  • 2
  • 5
  • I am seeing it on SharedPreferences.Editor.commit() – user1608385 Jan 15 '19 at 19:06
  • 1
    Doing a commit in the main thread could definitely lead to ANR, so that isn't surprising. – Hanson Char Jan 23 '19 at 16:21
  • This bug is marked as "fixed" in 2018. But it is still occurring in production now. Does that mean the fix is in Android framework code? – David Pisoni Mar 17 '20 at 16:14
  • why doing apply will cause ANR? it usually puts few data in the shareperference, event I sync it in the main thread, I think it should complete very fast, why it cause ANR? – Kevin Ding Dec 02 '21 at 04:39
5

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.

mjgrrrr
  • 241
  • 2
  • 13