標籤：

Android ANR 實例分析

03-15

什麼是ANR？

以下四個條件都可以造成ANR發生：

  • InputDispatching Timeout：5秒內無法響應屏幕觸摸事件或鍵盤輸入事件
  • BroadcastQueue Timeout ：在執行前台廣播（BroadcastReceiver）的onReceive()函數時10秒沒有處理完成，後台為60秒。
  • Service Timeout ：前台服務20秒內，後台服務在200秒內沒有執行完畢。
  • ContentProvider Timeout ：ContentProvider的publish在10s內沒進行完。

    jianshu.com/p/388166988

實例分析

我們測試過程中跑monkey測試的時候，發生了ANR，LOG非常多。但是分析原因的時候還是非常考驗思路。

需要三個文件

  • traces.txt traces狀態
  • threath.txt 這個是最後的進程狀態
  • logcat日誌

    日誌鏈接，想分析的自行下載

    鏈接：pan.baidu.com/s/1i0Lf2l

    提取碼：wutm

1.搜索ANR in這個關鍵字

12-27 01:18:59.865 562 591 E ActivityManager: ANR in com.android.music
12-27 01:18:59.865 562 591 E ActivityManager: PID: 5563
12-27 01:18:59.865 562 591 E ActivityManager: Reason: Broadcast of Intent { act=android.intent.action.MEDIA_BUTTON flg=0x10 cmp=com.android.music/.MediaButtonIntentReceiver (has extras) }
12-27 01:18:59.865 562 591 E ActivityManager: Load: 0.0 / 0.0 / 0.0
12-27 01:18:59.865 562 591 E ActivityManager: CPU usage from 5870ms to 375ms ago (2018-12-27 01:18:53.949 to 2018-12-27 01:18:59.444):
12-27 01:18:59.865 562 591 E ActivityManager: 105% 562/system_server: 103% user + 2.1% kernel / faults: 435 minor
12-27 01:18:59.865 562 591 E ActivityManager: 100% 30/kconsole: 0% user + 100% kernel
12-27 01:18:59.865 562 591 E ActivityManager: 3.6% 204/healthd: 0.5% user + 3% kernel
12-27 01:18:59.865 562 591 E ActivityManager: 2.3% 164/ueventd: 1.2% user + 1% kernel / faults: 1 minor
12-27 01:18:59.865 562 591 E ActivityManager: 2.3% 186/logd: 1% user + 1.2% kernel
12-27 01:18:59.865 562 591 E ActivityManager: 2% 235/log-watch: 1% user + 0.9% kernel
12-27 01:18:59.865 562 591 E ActivityManager: 0.9% 132/irq/78-0-006a: 0% user + 0.9% kernel
12-27 01:18:59.865 562 591 E ActivityManager: 0.9% 5579/kworker/1:1: 0% user + 0.9% kernel
12-27 01:18:59.865 562 591 E ActivityManager: 0.7% 230/netd: 0.3% user + 0.3% kernel
12-27 01:18:59.865 562 591 E ActivityManager: 0.5% 1125/com.android.phone: 0.3% user + 0.1% kernel / faults: 8 minor
12-27 01:18:59.865 562 591 E ActivityManager: 0.1% 287/logcatext: 0% user + 0% kernel
12-27 01:18:59.865 562 591 E ActivityManager: 0.1% 5112/com.android.commands.monkey: 0.1% user + 0% kernel / faults: 5 minor
12-27 01:18:59.865 562 591 E ActivityManager: 0.1% 7/rcu_preempt: 0% user + 0.1% kernel
12-27 01:18:59.865 562 591 E ActivityManager: 0% 24/ksoftirqd/3: 0% user + 0% kernel
12-27 01:18:59.865 562 591 E ActivityManager: 0.1% 194/vold: 0% user + 0.1% kernel
12-27 01:18:59.865 562 591 E ActivityManager: 0.1% 205/displayd: 0.1% user + 0% kernel
12-27 01:18:59.865 562 591 E ActivityManager: 0% 209/servicemanager: 0% user + 0% kernel
12-27 01:18:59.865 562 591 E ActivityManager: 0.1% 210/surfaceflinger: 0% user + 0.1% kernel
12-27 01:18:59.865 562 591 E ActivityManager: 54% TOTAL: 27% user + 27% kernel
12-27 01:18:59.865 562 591 E ActivityManager: CPU usage from 50244340ms to 50244340ms ago (1970-01-01 02:00:00.000 to 1970-01-01 02:00:00.000) with 0% awake:
12-27 01:18:59.865 562 591 E ActivityManager: 0% TOTAL: 0% user + 0% kernel
12-27 01:18:59.865 0 0 W KERNEL : [50232.754404] healthd: battery l=66 v=4082 t=30.9 h=2 st=2 chg=
12-27 01:18:59.990 562 594 W BatteryStatsService: Timeout reading modem stats
12-27 01:18:59.998 1125 1125 D RILJ : [9781]> RIL_REQUEST_GET_ACTIVITY_INFO [SUB0]
12-27 01:18:59.999 1125 1125 D RilRequest: [9781]< RIL_REQUEST_GET_ACTIVITY_INFO error: com.android.internal.telephony.CommandException: RADIO_NOT_AVAILABLE ret=
12-27 01:18:59.999 1125 1125 E PhoneInterfaceManager: [PhoneIntfMgr] queryModemActivityInfo: Empty response
12-27 01:18:59.999 1125 1522 E JavaBinder: !!! FAILED BINDER TRANSACTION !!! (parcel size = 276)
12-27 01:18:59.999 562 594 E BatteryStatsService: no controller energy info supplied
12-27 01:18:59.999 562 594 E BatteryStatsService: no controller energy info supplied
12-27 01:19:00.000 0 0 W KERNEL : [50232.884468] healthd: battery l=66 v=4082 t=30.9 h=2 st=2 chg=a
12-27 01:19:00.059 562 8694 ?

然後這裡可以看到ANR 的PID是5563

回到traces.txt 找一下這個 com.android.music

干他大爺的，發現沒有找到~~

不著急，

我們剛才看那個日誌的時候比較早，traces.txt可能會後面的日誌衝掉了原因是

Wrote stack traces to /data/anr/traces.txt

這個是每次發生anr的時候，想traces文件寫入數據的日誌

我們找最後一次寫入這個文件的日誌位置

12-27 03:02:54.175 0 0 W KERNEL : [56327.543907] .cpu_load[0] : 84
12-27 03:02:54.178 562 1364 I Process : Sending signal. PID: 562 SIG: 3
12-27 03:02:54.179 562 567 I art : Thread[2,tid=567,WaitingInMainSignalCatcherLoop,Thread*=0xa6d0c000,peer=0x12c010d0,"Signal Catcher"]: reacting to signal 3
12-27 03:02:54.179 562 567 I art :
12-27 03:02:54.180 0 0 W KERNEL : [56327.543921] .cpu_load[1] : 54
12-27 03:02:54.641 562 567 I art : Wrote stack traces to /data/anr/traces.txt
12-27 03:02:54.641 562 1364 I Process : Sending signal. PID: 1125 SIG: 3
12-27 03:02:54.641 1125 1128 I art : Thread[3,tid=1128,WaitingInMainSignalCatcherLoop,Thread*=0xa433fe00,peer=0x12c00670,"Signal Catcher"]: reacting to signal 3
12-27 03:02:54.641 0 0 W KERNEL : [56327.543932] .cpu_load[2] : 30
12-27 03:02:54.641 1125 1128 I art :
12-27 03:02:54.653 0 0 W KERNEL : [56327.543945] .cpu_load[3] : 16
12-27 03:02:54.693 1125 1128 I art : Wrote stack traces to /data/anr/traces.txt
12-27 03:02:54.698 0 0 W KERNEL : [56327.543958] .cpu_load[4] : 9
12-27 03:02:54.698 193 193 W : debuggerd: handling request: pid=210 uid=1000 gid=1003 tid=210
12-27 03:02:54.698 0 0 W KERNEL : [56327.543972] .yld_count : 570694
12-27 03:02:54.791 193 193 W : debuggerd: resuming target 210
12-27 03:02:54.791 0 0 W KERNEL : [56327.543986] .sched_count : 127372328
12-27 03:02:54.792 193 193 W : debuggerd: handling request: pid=221 uid=1041 gid=1005 tid=221
12-27 03:02:54.792 0 0 W KERNEL : [56327.544001] .sched_goidle : 25588776
12-27 03:02:54.870 193 193 W : debuggerd: resuming target 221
12-27 03:02:54.871 0 0 W KERNEL : [56327.544014] .avg_idle : 1000000
12-27 03:02:54.871 193 193 W : debuggerd: handling request: pid=222 uid=1047 gid=1005 tid=222
12-27 03:02:54.871 0 0 W KERNEL : [56327.544022] .max_idle_balance_cost : 500000
12-27 03:02:54.904 193 193 W : debuggerd: resuming target 222
12-27 03:02:54.905 0 0 W KERNEL : [56327.544030] .ttwu_count : 68703282
12-27 03:02:54.905 193 193 W : debuggerd: handling request: pid=223 uid=1019 gid=1019 tid=223
12-27 03:02:54.905 0 0 W KERNEL : [56327.544037] .ttwu_local : 31888109
12-27 03:02:54.917 193 193 W : debuggerd: resuming target 223
12-27 03:02:54.917 0 0 W KERNEL : [56327.544045] x0acfs_rq[1]:/bg_non_interactive
12-27 03:02:54.917 193 193 W : debuggerd: handling request: pid=226 uid=1046 gid=1006 tid=226
12-27 03:02:54.917 0 0 W KERNEL : [56327.544057] .exec_clock : 1419463.649513
12-27 03:02:54.968 193 193 W : debuggerd: resuming target 226
12-27 03:02:54.968 0 0 W KERNEL : [56327.544065] .MIN_vruntime : 0.000001
12-27 03:02:54.968 193 193 W : debuggerd: handling request: pid=227 uid=1013 gid=1031 tid=227
12-27 03:02:54.968 0 0 W KERNEL : [56327.544072] .min_vruntime : 10007865.678185
12-27 03:02:54.982 193 193 W : debuggerd: resuming target 227

Process : Sending signal. PID: 1125 SIG: 3

PID 1125 被發送了一個SIG3 然後我們查一下這個SIG 3

說明1125 被殺死了，信號值對應的數值如下

信號 值 處理動作 發出信號的原因
----------------------------------------------------------------------
SIGHUP 1 A 終端掛起或者控制進程終止
SIGINT 2 A 鍵盤中斷（如break鍵被按下）
SIGQUIT 3 C 鍵盤的退出鍵被按下
SIGILL 4 C 非法指令
SIGABRT 6 C 由abort(3)發出的退出指令
SIGFPE 8 C 浮點異常
SIGKILL 9 AEF Kill信號
SIGSEGV 11 C 無效的內存引用
SIGPIPE 13 A 管道破裂: 寫一個沒有讀埠的管道
SIGALRM 14 A 由alarm(2)發出的信號
SIGTERM 15 A 終止信號
SIGUSR1 30,10,16 A 用戶自定義信號1
SIGUSR2 31,12,17 A 用戶自定義信號2
SIGCHLD 20,17,18 B 子進程結束信號
SIGCONT 19,18,25 進程繼續（曾被停止的進程）
SIGSTOP 17,19,23 DEF 終止進程
SIGTSTP 18,20,24 D 控制終端（tty）上按下停止鍵
SIGTTIN 21,21,26 D 後台進程企圖從控制終端讀
SIGTTOU 22,22,27 D 後台進程企圖從控制終端寫

下面的信號沒在POSIX.1中列出，而在SUSv2列出

信號 值 處理動作 發出信號的原因

鏈接：www.cnblogs.com/taobataoma/archive/2007/08/30/875743.html

然後我們繼續搜下

從這個圖片看到了，這個1125不斷的被殺死，因為是系統進程，自己又無恥的啟動，反覆如此，就出現了上面的日誌。

然後繼續回到traces.txt裡面分析

看thread.txt裡面查看1125這個進程的名字是android.phone.

1125 1125 radio 20 0 0% S 1024340K 87388K fg m.android.phone com.android.phone
1125 1127 radio 29 9 0% S 1024340K 87388K fg Jit thread pool com.android.phone
1125 1128 radio 20 0 0% S 1024340K 87388K fg Signal Catcher com.android.phone
1125 1129 radio 20 0 0% S 1024340K 87388K fg JDWP com.android.phone

然後在看thread.txt裡面查看562這個進程的名字是system_server，如下圖

562 562 system 18 -2 0% S 1851968K 408908K fg system_server system_server
562 567 system 20 0 0% S 1851968K 408908K fg Signal Catcher system_server
562 569 system 20 0 0% S 1851968K 408908K fg ReferenceQueueD system_server
562 570 system 20 0 0% S 1851968K 408908K fg FinalizerDaemon system_server
562 571 system 20 0 0% S 1851968K 408908K fg FinalizerWatchd system_server
562 572 system 20 0 0% S 1851968K 408908K fg HeapTaskDaemon system_server
562 588 system 20 0 0% S 1851968K 408908K fg Binder:562_1 system_server

然後再在traces.txt裡面看

----- pid 562 at 2018-12-27 03:03:32 -----
Cmd line: system_server
Build fingerprint: Android/rk3288_pad/rk3288_pad:7.1.2/NHG47K/52:userdebug/test-keys
ABI: arm

這是system_server出現問題的時候記錄下來的日誌，然後繼續往下看

"main" prio=5 tid=1 Native
| group="main" sCount=1 dsCount=0 obj=0x73d514a0 self=0xae105400
| sysTid=562 nice=-2 cgrp=default sched=0/0 handle=0xb0eb2534
| state=S schedstat=( 265574536000 322529001630 703903 ) utm=21655 stm=4901 core=1 HZ=100
| stack=0xbe0b4000-0xbe0b6000 stackSize=8MB
| held mutexes=
native: #00 pc 00017418 /system/lib/libc.so (syscall+28)
native: #01 pc 00046eab /system/lib/libc.so (_ZL24__pthread_cond_timedwaitP23pthread_cond_internal_tP15pthread_mutex_tbPK8timespec+102)
native: #02 pc 000846d7 /system/lib/libmedia.so (_ZN7android11MediaPlayer7prepareEv+82)
native: #03 pc 0002b683 /system/lib/libmedia_jni.so (???)
native: #04 pc 00a5780f /data/dalvik-cache/arm/system@framework@boot.oat (Java_android_media_MediaPlayer__1prepare__+74)
at android.media.MediaPlayer._prepare(Native method)
at android.media.MediaPlayer.prepare(MediaPlayer.java:1365)
at android.media.Ringtone.setUri(Ringtone.java:298)
at android.media.Ringtone.setAudioAttributes(Ringtone.java:134)
at android.media.Ringtone.setStreamType(Ringtone.java:105)
at com.android.server.power.Notifier.playWirelessChargingStartedSound(Notifier.java:702)
at com.android.server.power.Notifier.-wrap0(Notifier.java:-1)
at com.android.server.power.Notifier$NotifierHandler.handleMessage(Notifier.java:728)
at android.os.Handler.dispatchMessage(Handler.java:102)
at android.os.Looper.loop(Looper.java:154)
at com.android.server.SystemServer.run(SystemServer.java:358)
at com.android.server.SystemServer.main(SystemServer.java:225)
at java.lang.reflect.Method.invoke!(Native method)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:912)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:802)

這是出現問題的棧指針和函數調用的情況，可以看到是

at android.media.MediaPlayer._prepare(Native method)

at android.media.MediaPlayer.prepare(MediaPlayer.java:1365)

這裡出現了問題，具體原因需要根據日誌去分析了

總結梳理一下流程

1125 這個是com.android.phone 是android 撥打電話的進程

562 這個是android_server 系統進程

這兩個在日誌裡面不斷的相愛相殺了很多次，從traces.txt的原因上來看是MediaPlayer.prepare阻塞的原因，但是android_server正常沒人惹他，他是不會發生這麼多次崩潰的，所以最終導致的原因應該是com.android.phone調用了system_server的東西。

然後為什麼com.android.phone會有問題呢？

繼續摸索了一下日誌

12-27 02:39:44.726 1125 1125 D RILJ : [8577]> RIL_REQUEST_GET_ACTIVITY_INFO [SUB0]
12-27 02:39:44.727 1125 1125 D RilRequest: [8577]< RIL_REQUEST_GET_ACTIVITY_INFO error: com.android.internal.telephony.CommandException: RADIO_NOT_AVAILABLE ret=
12-27 02:39:44.727 1125 1125 E PhoneInterfaceManager: [PhoneIntfMgr] queryModemActivityInfo: Empty response
12-27 02:39:44.732 562 594 E BatteryStatsService: modem info is invalid: ModemActivityInfo{ mTimestamp=0 mSleepTimeMs=0 mIdleTimeMs=0 mTxTimeMs[]=[0, 0, 0, 0, 0] mRxTimeMs=0 mEnergyUsed=0}
12-27 02:39:44.735 562 594 E BatteryStatsService: no controller energy info supplied
12-27 02:39:44.735 562 594 E BatteryStatsService: no controller energy info supplied
12-27 02:39:44.736 1125 1125 D RILJ : [8578]> RIL_REQUEST_GET_ACTIVITY_INFO [SUB0]
12-27 02:39:44.736 1125 1125 D RilRequest: [8578]< RIL_REQUEST_GET_ACTIVITY_INFO error: com.android.internal.telephony.CommandException: RADIO_NOT_AVAILABLE ret=
12-27 02:39:44.736 1125 1125 E PhoneInterfaceManager: [PhoneIntfMgr] queryModemActivityInfo: Empty response
12-27 02:39:44.741 562 594 E BatteryStatsService: modem info is invalid: ModemActivityInfo{ mTimestamp=0 mSleepTimeMs=0 mIdleTimeMs=0 mTxTimeMs[]=[0, 0, 0, 0, 0] mRxTimeMs=0 mEnergyUsed=0}
12-27 02:39:44.745 562 594 E BatteryStatsService: no controller energy info supplied
12-27 02:39:44.745 562 594 E BatteryStatsService: no controller energy info supplied

1125 調用了modem相關的東西，也就是在monkey測試過程中撥打了電話和，但是因為我們是平板項目，硬體上根本是沒有modem的，原聲的系統是也是去掉了這個apk的，我們是為了做暗碼組合鍵功能才調出來的。

實際分析如上，如果有不正確的，請留言指正，謝謝

推薦閱讀：

TAG:Android |