ANR分析

产生ANR的原因

• While your activity is in the foreground, your app has not responded to an input event or BroadcastReceiver (such as key press or screen touch events) within 5 seconds.
• While you do not have an activity in the foreground, your BroadcastReceiver hasn’t finished executing within a considerable amount of time.

分析日志

traces文件位置

04-14 15:38:51.772 1967-1976/? I/art: Wrote stack traces to '/data/anr/traces.txt'

使用adb pull /data/anr/traces.txt E:\命令就能导出traces文件到pc.

有些设备会根据触发anr的程序包名和时间对traces文件进行重命名，上述方法就取不到traces文件了。就需要用到adb shell命令了：

adb shell //进入 adb shell
cat /data/anr/traces-xxx.txt > /mnt/sdcard/traces.txt //将 traces文件从 anr目录中导出到 sdcard中。
exit //退出 adb shell
adb pull /mnt/sdcard/traces.txt C:\traces.txt //将 sdcard中的 traces文件导出到pc中。

CPU消耗

出现ANR后，系统会给出CPU的使用情况

04-14 15:38:51.772 1967-1976/? I/art: Wrote stack traces to '/data/anr/traces.txt'
04-14 15:38:51.775 1580-1671/? E/ActivityManager: ANR in com.xiaoyusan.android (com.xiaoyusan.android/.MainActivity)
                                                  PID: 30825
                                                  Reason: Input dispatching timed out (com.xiaoyusan.android/com.xiaoyusan.android.MainActivity, 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: 21.  Wait queue head age: 17811.4ms.)
                                                  Load: 8.14 / 7.13 / 7.13
                                                  CPU usage from 12232ms to 0ms ago (2018-04-14 15:38:36.425 to 2018-04-14 15:38:48.657):
                                                    98% 30825/com.xiaoyusan.android: 97% user + 1.4% kernel / faults: 890 minor 98 major
                                                    23% 1580/system_server: 14% user + 9.2% kernel / faults: 7731 minor 778 major
                                                    4.7% 1967/com.android.systemui: 3.2% user + 1.4% kernel / faults: 4035 minor 87 major
                                                    4.1% 572/surfaceflinger: 2% user + 2.1% kernel / faults: 326 minor
                          ....                         
                                                    0% 740/jbd2/dm-1-8: 0% user + 0% 

从12232ms前到0ms前CPU的平均负载：

CPU usage from 12232ms to 0ms ago (2018-04-14 15:38:36.425 to 2018-04-14 15:38:48.657):

com.xiaoyusan.android进程消耗了98%的CPU, 说明这个进程内可能存在耗时操作，并且堵塞了主线程：

98% 30825/com.xiaoyusan.android: 97% user + 1.4% kernel / faults: 890 minor 98 major

然后会打印anr traces, 显示是进程id为20401的com.xiaoyusan.android进程出了问题。

procrank:
// Exception from procrank:
java.io.IOException: Cannot run program "procrank": error=13, Permission denied
anr traces:

----- pid 30401 at 2018-04-09 15:54:05 -----
Cmd line: com.xiaoyusan.android
Build fingerprint: 'xiaomi/tiffany/tiffany:7.1.2/N2G47H/V9.0.3.0.NDBCNEI:user/release-keys'
ABI: 'arm'
Build type: optimized
Zygote loaded classes=4571 post zygote classes=2561
Intern table: 47411 strong; 1381 weak
JNI: CheckJNI is on; globals=770 (plus 543 weak)
Libraries: /data/app/com.xiaoyusan.android-1/lib/arm/libBugly.so /data/app/com.xiaoyusan.android-1/lib/arm/libjpush217.so /data/app/com.xiaoyusan.android-1/lib/arm/libweibosdkcore.so /data/user/0/com.xiaoyusan.android/app_tbs/core_share/liblinuxtoolsfortbssdk_jni.so /data/user/0/com.xiaoyusan.android/app_tbs/core_share/libtbs_crash_handler.so /data/user/0/com.xiaoyusan.android/app_tbs/core_share/libwebp_base.so /system/app/WebViewGoogle/WebViewGoogle.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/libmiuiclassproxy.so /system/lib/libmiuinative.so /system/lib/libsechook.so /system/lib/libwebviewchromium_loader.so /system/lib/libwebviewchromium_plat_support.so /vendor/lib/libqti_performance.so libjavacore.so libopenjdk.so (20)
/data/user/0/com.xiaoyusan.android/app_tbs/core_unzip_tmp/TencentLocationSDK.dex: speed
/data/user/0/com.xiaoyusan.android/app_tbs/core_unzip_tmp/tbs_sdk_extension_dex.dex: speed
/data/user/0/com.xiaoyusan.android/app_tbs/core_unzip_tmp/fullscreen_player_dex.dex: speed
/data/user/0/com.xiaoyusan.android/app_tbs/core_unzip_tmp/qziper_dex.dex: speed
/data/user/0/com.xiaoyusan.android/app_tbs/core_unzip_tmp/game_impl_dex.dex: speed
/data/user/0/com.xiaoyusan.android/app_tbs/core_unzip_tmp/tbs_bugly_dex.dex: speed
/data/user/0/com.xiaoyusan.android/app_tbs/core_unzip_tmp/video_impl_dex.dex: speed
/data/user/0/com.xiaoyusan.android/app_tbs/core_share/tbs_sdk_extension_dex.dex: speed
/data/user/0/com.xiaoyusan.android/app_tbs/core_unzip_tmp/tbs_game_sandbox_dex.dex: speed
/data/user/0/com.xiaoyusan.android/app_tbs/core_unzip_tmp/tbs_jars_fusion_dex.dex: speed
/data/user/0/com.xiaoyusan.android/app_tbs/core_unzip_tmp/miniqb_dex.dex: speed
/data/user/0/com.xiaoyusan.android/app_tbs/core_share/tbs_jars_fusion_dex.dex: speed
/system/framework/oat/arm/QPerformance.odex: speed
/data/app/com.xiaoyusan.android-1/oat/arm/base.odex: interpret-only
/system/framework/oat/arm/volley.odex: speed
/system/app/WebViewGoogle/oat/arm/WebViewGoogle.odex: speed
Current JIT code cache size: 78KB
Current JIT data cache size: 99KB
Current JIT capacity: 256KB
...

suspend all histogram:  Sum: 559us 99% C.I. 3us-115us Avg: 37.266us Max: 115us
DALVIK THREADS (63):
"Thread-92" prio=5 tid=62 Runnable
  | group="main" sCount=0 dsCount=0 obj=0x13cfadc0 self=0xc3c10d00
  | sysTid=30854 nice=0 cgrp=default sched=0/0 handle=0xbb0fa920
  | state=R schedstat=( 14519271 15400417 53 ) utm=0 stm=1 core=3 HZ=100
  | stack=0xbaff8000-0xbaffa000 stackSize=1038KB
  | held mutexes= "mutator lock"(shared held)
  at java.lang.reflect.Array.newInstance(Array.java:109)
  at com.tencent.smtt.sdk.a.a.a(unavailable:-1)
  at com.tencent.smtt.sdk.a.a.a(unavailable:-1)
  at com.tencent.smtt.sdk.a.a.b(unavailable:-1)
  at com.tencent.smtt.sdk.a.a.a(unavailable:-1)
  at com.tencent.smtt.utils.q.a(unavailable:-1)
  at com.tencent.smtt.utils.n.a(unavailable:-1)
  at com.tencent.smtt.sdk.TbsLogReport.b(unavailable:-1)
  - locked <0x0ce7c7b9> (a com.tencent.smtt.sdk.TbsLogReport)
  at com.tencent.smtt.sdk.ar.run(unavailable:-1)
  at java.lang.Thread.run(Thread.java:760)

"Thread-Pool-IoBound-1" prio=5 tid=33 Runnable
  | group="main" sCount=0 dsCount=0 obj=0x13be4310 self=0xc3a8a400
  | sysTid=30848 nice=11 cgrp=bg_non_interactive sched=0/0 handle=0xc17f7920
  | state=R schedstat=( 39091150 38627085 109 ) utm=3 stm=0 core=4 HZ=100
  | stack=0xc16f5000-0xc16f7000 stackSize=1038KB
  | held mutexes= "mutator lock"(shared held)
  native: #00 pc 00351041  /system/lib/libart.so (_ZN3art15DumpNativeStackERNSt3__113basic_ostreamIcNS0_11char_traitsIcEEEEiP12BacktraceMapPKcPNS_9ArtMethodEPv+128)
  native: #01 pc 00331799  /system/lib/libart.so (_ZNK3art6Thread9DumpStackERNSt3__113basic_ostreamIcNS1_11char_traitsIcEEEEbP12BacktraceMap+308)
  native: #02 pc 003437ad  /system/lib/libart.so (_ZN3art14DumpCheckpoint3RunEPNS_6ThreadE+620)
  native: #03 pc 0033231f  /system/lib/libart.so (_ZN3art6Thread21RunCheckpointFunctionEv+146)
  native: #04 pc 003f4009  /system/lib/libart.so (_ZN3artL12GoToRunnableEPNS_6ThreadE+52)
  native: #05 pc 003f4329  /system/lib/libart.so (_ZN3art25JniMethodEndWithReferenceEP8_jobjectjPNS_6ThreadE+12)
  native: #06 pc 0000ca87 
  ...

打印的第一个线程很可能是出问题的线程:

suspend all histogram:  Sum: 559us 99% C.I. 3us-115us Avg: 37.266us Max: 115us
DALVIK THREADS (63):
"Thread-92" prio=5 tid=62 Runnable
  | group="main" sCount=0 dsCount=0 obj=0x13cfadc0 self=0xc3c10d00
  | sysTid=30854 nice=0 cgrp=default sched=0/0 handle=0xbb0fa920
  | state=R schedstat=( 14519271 15400417 53 ) utm=0 stm=1 core=3 HZ=100
  | stack=0xbaff8000-0xbaffa000 stackSize=1038KB
  | held mutexes= "mutator lock"(shared held)
  at java.lang.reflect.Array.newInstance(Array.java:109)
  at com.tencent.smtt.sdk.a.a.a(unavailable:-1)
  at com.tencent.smtt.sdk.a.a.a(unavailable:-1)
  at com.tencent.smtt.sdk.a.a.b(unavailable:-1)
  at com.tencent.smtt.sdk.a.a.a(unavailable:-1)
  at com.tencent.smtt.utils.q.a(unavailable:-1)
  at com.tencent.smtt.utils.n.a(unavailable:-1)
  at com.tencent.smtt.sdk.TbsLogReport.b(unavailable:-1)
  - locked <0x0ce7c7b9> (a com.tencent.smtt.sdk.TbsLogReport)
  at com.tencent.smtt.sdk.ar.run(unavailable:-1)
  at java.lang.Thread.run(Thread.java:760)
 ```

 `- locked`代表`TbsLogReport#b()`方法中持有`TbsLogReport`对象`a`的锁，也就是存在`Synchronized(TbsLogReport.this)`语句。

 ```
 at com.tencent.smtt.sdk.TbsLogReport.b(unavailable:-1)
  - locked <0x0ce7c7b9> (a com.tencent.smtt.sdk.TbsLogReport)

那就很可能是子线程和主线程都锁住了同一个对象，然后子线程耗时，导致主线程获取不到锁，进而导致ANR. 例如：

@Override
public void onClick(View v) {
    // The worker thread holds a lock on lockedResource
   new LockTask().execute(data);

   synchronized (lockedResource) {
       // The main thread requires lockedResource here
       // but it has to wait until LockTask finishes using it.
   }
}

public class LockTask extends AsyncTask<Integer[], Integer, Long> {
   @Override
   protected Long doInBackground(Integer[]... params) {
       synchronized (lockedResource) {
           // This is a long-running operation, which makes
           // the lock last for a long time
           BubbleSort.sort(params[0]);
       }
   }
}

注意：经过测试，假设两个线程分别含有Synchronized(TbsLogReport.this)和Synchronized(TbsLogReport.class)锁，那么这两个线程都要等对方释放，才能获取到锁。

“main”代表主线程，Blocked是线程状态，代表主线程被阻塞，就是上述子线程中的锁没有释放，导致主线程被锁住，引发ANR.

"main" prio=5 tid=1 Blocked
  | group="main" sCount=1 dsCount=0 obj=0x75d48000 self=0xec405400
  | sysTid=10945 nice=-4 cgrp=default sched=0/0 handle=0xef082538
  | state=S schedstat=( 2441995099 1350925397 6738 ) utm=199 stm=45 core=1 HZ=100
  | stack=0xff18a000-0xff18c000 stackSize=8MB
  | held mutexes=
  at android.app.Activity.setResult(Activity.java:5131)
  - waiting to lock <0x09a63986> (a com.xiaoyusan.android.MainActivity) held by thread 66
  at com.xiaoyusan.android.api.NavigationApi.back(NavigationApi.java:85)
  at com.xiaoyusan.android.page.HomePage.onBackPressed(HomePage.java:115)
  at com.xiaoyusan.android.MainActivity.onBackPressed(MainActivity.java:161)
  at android.app.Activity.onKeyUp(Activity.java:2808)
  at android.view.KeyEvent.dispatch(KeyEvent.java:2702)
  at android.app.Activity.dispatchKeyEvent(Activity.java:3113)
  ...

线程状态:

ThreadState (defined at “dalvik/vm/thread.h “) THREAD_UNDEFINED = -1, /* makes enum compatible with int32_t / 
THREAD_ZOMBIE = 0, / TERMINATED / 
THREAD_RUNNING = 1, / RUNNABLE or running now / THREAD_TIMED_WAIT = 2, / 
TIMED_WAITING in Object.wait() / 
THREAD_MONITOR = 3, / BLOCKED on a monitor / 
THREAD_WAIT = 4, / WAITING in Object.wait() / THREAD_INITIALIZING= 5, / allocated, not yet running / 
THREAD_STARTING = 6, / started, not yet on thread list / 
THREAD_NATIVE = 7, / off in a JNI native method / THREAD_VMWAIT = 8, / waiting on a VM resource / THREAD_SUSPENDED = 9, / suspended, usually by GC or debugger */

• 官网镇楼
• 如何使用Monkey
• Android 系统稳定性 - ANR 解析
• Monkey原理探讨
• 如何分析Monkey
• bugly解决anr