Android ANR 分析

首先贴一下trace 文件

Process: com.oppo.reader
PID: 20358
Time: 2933175644_1545041895232
Flags: 0x38d83e44
Package: com.oppo.reader v62301 (6.2.3.20181030)
PID: 20358
Foreground: Yes
Activity: com.oppo.reader/com.zhangyue.iReader.read.ui.Activity_BookBrowser_TXT
Subject: Input dispatching timed out (Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago.  Wait queue length: 2.  Wait queue head age: 8825.0ms.)
Build: OPPO/PBFM00/PBFM00:8.1.0/OPM1.171019.026/1541766248:user/release-keysCPU usage from 0ms to 6451ms later (2018-12-17 18:18:08.726 to 2018-12-17 18:18:15.177):100% 20358/com.oppo.reader: 97% user + 3.5% kernel / faults: 4111 minor 3 major39% 1895/system_server: 27% user + 11% kernel / faults: 3126 minor 26 major0.2% 1167/media.codec: 0.2% user + 0% kernel / faults: 4081 minor4% 17827/com.android.systemui: 3.2% user + 0.7% kernel / faults: 1640 minor 224 major3.7% 2835/com.android.phone: 3.2% user + 0.4% kernel / faults: 434 minor3.4% 687/surfaceflinger: 2.4% user + 0.9% kernel / faults: 454 minor
26% TOTAL: 20% user + 4.6% kernel + 0.5% iowait + 0.3% irq + 0.1% softirq----- pid 20358 at 2018-12-17 18:18:09 -----
Cmd line: com.oppo.reader
Build fingerprint: 'OPPO/PBFM00/PBFM00:8.1.0/OPM1.171019.026/1541766248:user/release-keys'
ABI: 'arm'
Build type: optimized
Zygote loaded classes=5110 post zygote classes=3166
Intern table: 52731 strong; 145 weak
JNI: CheckJNI is off; globals=727 (plus 79 weak)
Libraries: /data/app/com.oppo.reader-NTuEuWlogpCo1aD9HtyDhQ==/lib/arm/libUiControl.so /data/app/com.oppo.reader-NTuEuWlogpCo1aD9HtyDhQ==/lib/arm/libtingReader.so /system/app/WebViewGoogleNX/WebViewGoogleNX.apk!/lib/armeabi-v7a/libwebviewchromium.so /system/lib/libandroid.so /system/lib/libcompiler_rt.so /system/lib/libjavacrypto.so /system/lib/libjnigraphics.so /system/lib/libmedia_jni.so /system/lib/libqti_performance.so /system/lib/libsoundpool.so /system/lib/libwebviewchromium_loader.so /system/lib/libwebviewchromium_plat_support.so libjavacore.so libopenjdk.so (14)
Heap: 24% free, 16MB/22MB; 262809 objects
Dumping cumulative Gc timings
Start Dumping histograms for 8 iterations for concurrent copying
ProcessMarkStack:   Sum: 430.463ms 99% C.I. 12.291ms-126.080ms Avg: 53.807ms Max: 127.672msProfileSaver total_ms_of_work=60
ProfileSaver max_number_profile_entries_cached=0
ProfileSaver total_number_of_hot_spikes=2
ProfileSaver total_number_of_wake_ups=4
Number of JIT inline cache deoptimizations: 2suspend all histogram: Sum: 1.234ms 99% C.I. 9us-160.399us Avg: 31.641us Max: 169us
DALVIK THREADS (70):
"Signal Catcher" daemon prio=5 tid=3 Runnable| group="system" sCount=0 dsCount=0 flags=0 obj=0x13500280 self=0xe6c0fc00| sysTid=20364 nice=0 cgrp=default sched=0/0 handle=0xdcbfe970| state=R schedstat=( 27239057 2910573 19 ) utm=2 stm=0 core=0 HZ=100| stack=0xdcb04000-0xdcb06000 stackSize=1006KB| held mutexes= "mutator lock"(shared held)native: #00 pc 002e8b57  /system/lib/libart.so (art::DumpNativeStack(std::__1::basic_ostream<char, std::__1::char_traits<char>>&, int, BacktraceMap*, char const*, art::ArtMethod*, void*)+130)native: #01 pc 0037b7f9  /system/lib/libart.so (art::Thread::DumpStack(std::__1::basic_ostream<char, std::__1::char_traits<char>>&, bool, BacktraceMap*, bool) const+204)native: #02 pc 00377d2b  /system/lib/libart.so (art::Thread::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char>>&, bool, BacktraceMap*, bool) const+34)native: #03 pc 0038f8fb  /system/lib/libart.so (art::DumpCheckpoint::Run(art::Thread*)+698)native: #04 pc 0038947d  /system/lib/libart.so (art::ThreadList::RunCheckpoint(art::Closure*, art::Closure*)+320)native: #05 pc 00388f7b  /system/lib/libart.so (art::ThreadList::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char>>&, bool)+530)native: #06 pc 00388c9b  /system/lib/libart.so (art::ThreadList::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char>>&)+626)native: #07 pc 003652d3  /system/lib/libart.so (art::Runtime::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char>>&)+122)native: #08 pc 0036d9b3  /system/lib/libart.so (art::SignalCatcher::HandleSigQuit()+1282)native: #09 pc 0036c91b  /system/lib/libart.so (art::SignalCatcher::Run(void*)+330)native: #10 pc 000473f3  /system/lib/libc.so (__pthread_start(void*)+22)native: #11 pc 0001afb1  /system/lib/libc.so (__start_thread+32)(no managed stack frames)"main" prio=5 tid=1 Blocked| group="main" sCount=1 dsCount=0 flags=1 obj=0x71ebca68 self=0xe6c0f000| sysTid=20358 nice=-10 cgrp=default sched=0/0 handle=0xea9254a4| state=S schedstat=( 2882074832 469149273 2373 ) utm=241 stm=47 core=1 HZ=100| stack=0xff789000-0xff78b000 stackSize=8MB| held mutexes=at com.zhangyue.iReader.DB.DBAdapter.execSQL(SourceFile:2512)- waiting to lock <0x08d75003> (a com.zhangyue.iReader.DB.DBAdapter) held by thread 66at com.zhangyue.iReader.DB.DBAdapter.queryBookIDWithoutPath(SourceFile:1497)at com.zhangyue.iReader.read.ui.BookBrowserFragment.u(SourceFile:1223)at com.zhangyue.iReader.read.ui.BookBrowserFragment.U(SourceFile:368)at com.zhangyue.iReader.read.ui.cc.run(SourceFile:3098)at android.os.Handler.handleCallback(Handler.java:790)at android.os.Handler.dispatchMessage(Handler.java:99)at android.os.Looper.loop(Looper.java:198)at android.app.ActivityThread.main(ActivityThread.java:7038)at java.lang.reflect.Method.invoke(Native method)at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:519)at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:836)"Jit thread pool worker thread 0" daemon prio=5 tid=2 Native| group="main" sCount=1 dsCount=0 flags=1 obj=0x135001f8 self=0xdcd1f000| sysTid=20363 nice=9 cgrp=default sched=0/0 handle=0xdccff970| state=S schedstat=( 803558025 113797923 579 ) utm=76 stm=4 core=6 HZ=100| stack=0xdcc01000-0xdcc03000 stackSize=1022KB| held mutexes=kernel: (couldn't read /proc/self/task/20363/stack)native: #00 pc 00018e20  /system/lib/libc.so (syscall+28)native: #01 pc 000b79d1  /system/lib/libart.so (art::ConditionVariable::WaitHoldingLocks(art::Thread*)+80)native: #02 pc 00390b81  /system/lib/libart.so (art::ThreadPool::GetTask(art::Thread*)+172)native: #03 pc 003904f7  /system/lib/libart.so (art::ThreadPoolWorker::Run()+62)native: #04 pc 00390115  /system/lib/libart.so (art::ThreadPoolWorker::Callback(void*)+92)native: #05 pc 000473f3  /system/lib/libc.so (__pthread_start(void*)+22)native: #06 pc 0001afb1  /system/lib/libc.so (__start_thread+32)(no managed stack frames)"ReferenceQueueDaemon" daemon prio=5 tid=4 Waiting| group="system" sCount=1 dsCount=0 flags=1 obj=0x13500308 self=0xdca14600| sysTid=20365 nice=4 cgrp=default sched=0/0 handle=0xc9e29970| state=S schedstat=( 34968799 11582865 55 ) utm=2 stm=1 core=4 HZ=100| stack=0xc9d27000-0xc9d29000 stackSize=1038KB| held mutexes=at java.lang.Object.wait(Native method)- waiting on <0x03602b80> (a java.lang.Class<java.lang.ref.ReferenceQueue>)at java.lang.Daemons$ReferenceQueueDaemon.runInternal(Daemons.java:183)- locked <0x03602b80> (a java.lang.Class<java.lang.ref.ReferenceQueue>)at java.lang.Daemons$Daemon.run(Daemons.java:108)at java.lang.Thread.run(Thread.java:764)"OkHttp https://icloud.zhangyue.com/..." prio=5 tid=66 Native| group="main" sCount=1 dsCount=0 flags=1 obj=0x133c0a30 self=0xc4ca9200| sysTid=21822 nice=0 cgrp=default sched=0/0 handle=0xbe396970| state=S schedstat=( 14565089915 55131141 764 ) utm=1423 stm=33 core=2 HZ=100| stack=0xbe294000-0xbe296000 stackSize=1038KB| held mutexes=kernel: (couldn't read /proc/self/task/21822/stack)native: #00 pc 00018e20  /system/lib/libc.so (syscall+28)native: #01 pc 000b79d1  /system/lib/libart.so (art::ConditionVariable::WaitHoldingLocks(art::Thread*)+80)native: #02 pc 003e2949  /system/lib/libart.so (art::GoToRunnable(art::Thread*)+300)native: #03 pc 003e27ed  /system/lib/libart.so (art::JniMethodEnd(unsigned int, art::Thread*)+8)native: #04 pc 00404d45  /system/framework/arm/boot-framework.oat (Java_android_database_sqlite_SQLiteConnection_nativeExecuteForChangedRowCount__JJ+132)at android.database.sqlite.SQLiteConnection.nativeExecuteForChangedRowCount(Native method)at android.database.sqlite.SQLiteConnection.executeForChangedRowCount(SQLiteConnection.java:748)at android.database.sqlite.SQLiteSession.executeForChangedRowCount(SQLiteSession.java:754)at android.database.sqlite.SQLiteStatement.executeUpdateDelete(SQLiteStatement.java:64)at android.database.sqlite.SQLiteDatabase.updateWithOnConflict(SQLiteDatabase.java:1658)at android.database.sqlite.SQLiteDatabase.update(SQLiteDatabase.java:1604)at com.zhangyue.iReader.DB.a.update(SourceFile:129)at com.zhangyue.iReader.DB.DBAdapter.update(SourceFile:4224)at dt.d.b(SourceFile:112)at com.zhangyue.iReader.DB.DBAdapter.updateHighLightByPostion(SourceFile:1657)at df.t.b(SourceFile:269)- locked <0x08d75003> (a com.zhangyue.iReader.DB.DBAdapter)at df.t.a(SourceFile:66)at df.al.a(SourceFile:118)at df.am.onHttpEvent(SourceFile:88)at com.zhangyue.net.p$b.onHttpEvent(SourceFile:138)at com.zhangyue.net.a.a(SourceFile:796)at com.zhangyue.net.a.a(SourceFile:63)at com.zhangyue.net.c.onResponse(SourceFile:698)at okhttp3.RealCall$AsyncCall.execute(SourceFile:153)at okhttp3.internal.NamedRunnable.run(SourceFile:32)at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1162)at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:636)at java.lang.Thread.run(Thread.java:764)

开头会告诉你，是哪个包ANR 了。所以，以后搜索ANR 可以在log 里面搜索：

Cmd line: com.oppo.reader

后面替换成你的包名。

第一步：查看主线程

"main" prio=5 tid=1 Blocked| group="main" sCount=1 dsCount=0 flags=1 obj=0x71ebca68 self=0xe6c0f000| sysTid=20358 nice=-10 cgrp=default sched=0/0 handle=0xea9254a4| state=S schedstat=( 2882074832 469149273 2373 ) utm=241 stm=47 core=1 HZ=100| stack=0xff789000-0xff78b000 stackSize=8MB| held mutexes=at com.zhangyue.iReader.DB.DBAdapter.execSQL(SourceFile:2512)- waiting to lock <0x08d75003> (a com.zhangyue.iReader.DB.DBAdapter) held by thread 66at com.zhangyue.iReader.DB.DBAdapter.queryBookIDWithoutPath(SourceFile:1497)at com.zhangyue.iReader.read.ui.BookBrowserFragment.u(SourceFile:1223)at com.zhangyue.iReader.read.ui.BookBrowserFragment.U(SourceFile:368)at com.zhangyue.iReader.read.ui.cc.run(SourceFile:3098)at android.os.Handler.handleCallback(Handler.java:790)at android.os.Handler.dispatchMessage(Handler.java:99)at android.os.Looper.loop(Looper.java:198)at android.app.ActivityThread.main(ActivityThread.java:7038)at java.lang.reflect.Method.invoke(Native method)at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:519)at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:836)

- waiting to lock <0x08d75003> (a com.zhangyue.iReader.DB.DBAdapter) held by thread 66
他说，在等待一个锁，0x08d75003。你可以在trace 里面搜索这个字符，或者后面说，held by thread 66，那就搜索线程66

tid=66

第二步：找到线程66

  "OkHttp https://icloud.zhangyue.com/..." prio=5 tid=66 Native| group="main" sCount=1 dsCount=0 flags=1 obj=0x133c0a30 self=0xc4ca9200| sysTid=21822 nice=0 cgrp=default sched=0/0 handle=0xbe396970| state=S schedstat=( 14565089915 55131141 764 ) utm=1423 stm=33 core=2 HZ=100| stack=0xbe294000-0xbe296000 stackSize=1038KB| held mutexes=kernel: (couldn't read /proc/self/task/21822/stack)native: #00 pc 00018e20  /system/lib/libc.so (syscall+28)native: #01 pc 000b79d1  /system/lib/libart.so (art::ConditionVariable::WaitHoldingLocks(art::Thread*)+80)native: #02 pc 003e2949  /system/lib/libart.so (art::GoToRunnable(art::Thread*)+300)native: #03 pc 003e27ed  /system/lib/libart.so (art::JniMethodEnd(unsigned int, art::Thread*)+8)native: #04 pc 00404d45  /system/framework/arm/boot-framework.oat (Java_android_database_sqlite_SQLiteConnection_nativeExecuteForChangedRowCount__JJ+132)at android.database.sqlite.SQLiteConnection.nativeExecuteForChangedRowCount(Native method)at android.database.sqlite.SQLiteConnection.executeForChangedRowCount(SQLiteConnection.java:748)at android.database.sqlite.SQLiteSession.executeForChangedRowCount(SQLiteSession.java:754)at android.database.sqlite.SQLiteStatement.executeUpdateDelete(SQLiteStatement.java:64)at android.database.sqlite.SQLiteDatabase.updateWithOnConflict(SQLiteDatabase.java:1658)at android.database.sqlite.SQLiteDatabase.update(SQLiteDatabase.java:1604)at com.zhangyue.iReader.DB.a.update(SourceFile:129)at com.zhangyue.iReader.DB.DBAdapter.update(SourceFile:4224)at dt.d.b(SourceFile:112)at com.zhangyue.iReader.DB.DBAdapter.updateHighLightByPostion(SourceFile:1657)at df.t.b(SourceFile:269)- locked <0x08d75003> (a com.zhangyue.iReader.DB.DBAdapter)at df.t.a(SourceFile:66)at df.al.a(SourceFile:118)at df.am.onHttpEvent(SourceFile:88)at com.zhangyue.net.p$b.onHttpEvent(SourceFile:138)at com.zhangyue.net.a.a(SourceFile:796)at com.zhangyue.net.a.a(SourceFile:63)at com.zhangyue.net.c.onResponse(SourceFile:698)at okhttp3.RealCall$AsyncCall.execute(SourceFile:153)at okhttp3.internal.NamedRunnable.run(SourceFile:32)at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1162)at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:636)at java.lang.Thread.run(Thread.java:764)

问下了同事， - locked <0x08d75003> (a com.zhangyue.iReader.DB.DBAdapter) 表示，从这行的堆栈开始，进入synchronized 代码块。（至于是不是，可以自己去获取堆栈，尝试下。）
那么，也就是在这里，子线程执行代码，占用了 - locked <0x08d75003> (a com.zhangyue.iReader.DB.DBAdapter)这个锁。

第三步：处理

怎么处理呢？

把没有用的锁，去掉。程序里面不要随意的加锁
我们这里是因为一大坨代码，都写在了执行事务里，导致，执行事务的时候，占用了SQLite 链接。导致主线程拿不到SQLite 的锁。

其他技巧

1.如果你觉得是某一块代码执行时间过长导致ANR,那么可以把这一块代码换成下面这个，看看会不会ANR.

        long begin  = System.currentTimeMillis();while(System.currentTimeMillis() - begin < 1000 * 60 * 10){a = 50;DBAdapter.getInstance().queryALLBook();}

上面这块代码，会执行10分钟。里面不停的执行SQL 操作。