Android ANR 实例分析
什么是ANR?
以下四個條件都可以造成ANR發生:
- InputDispatching Timeout:5秒內無法響應屏幕觸摸事件或鍵盤輸入事件
- BroadcastQueue Timeout :在執行前臺廣播(BroadcastReceiver)的onReceive()函數時10秒沒有處理完成,后臺為60秒。
- Service Timeout :前臺服務20秒內,后臺服務在200秒內沒有執行完畢。
- ContentProvider Timeout :ContentProvider的publish在10s內沒進行完。
https://www.jianshu.com/p/388166988cef
實例分析
我們測試過程中跑monkey測試的時候,發生了ANR,LOG非常多。但是分析原因的時候還是非常考驗思路。
需要三個文件
- traces.txt traces狀態
- threath.txt 這個是最后的進程狀態
- logcat日志
日志鏈接,想分析的自行下載
鏈接:https://pan.baidu.com/s/1i0Lf2luKbbEwXMATKErI8w
提取碼: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文件寫入數據的日志
我們找最后一次寫入這個文件的日志位置
Process : Sending signal. PID: 1125 SIG: 3
PID 1125 被發送了一個SIG3 然后我們查一下這個SIG 3
說明1125 被殺死了,信號值對應的數值如下
鏈接: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.phone1125 1127 radio 29 9 0% S 1024340K 87388K fg Jit thread pool com.android.phone1125 1128 radio 20 0 0% S 1024340K 87388K fg Signal Catcher com.android.phone1125 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_server562 567 system 20 0 0% S 1851968K 408908K fg Signal Catcher system_server562 569 system 20 0 0% S 1851968K 408908K fg ReferenceQueueD system_server562 570 system 20 0 0% S 1851968K 408908K fg FinalizerDaemon system_server562 571 system 20 0 0% S 1851968K 408908K fg FinalizerWatchd system_server562 572 system 20 0 0% S 1851968K 408908K fg HeapTaskDaemon system_server562 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會有問題呢?
繼續摸索了一下日志
1125 調用了modem相關的東西,也就是在monkey測試過程中撥打了電話和,但是因為我們是平板項目,硬件上根本是沒有modem的,原聲的系統是也是去掉了這個apk的,我們是為了做暗碼組合鍵功能才調出來的。
實際分析如上,如果有不正確的,請留言指正,謝謝
歡迎關注微信公眾號-嵌入式Linux
覺得不錯,請幫忙轉發,點贊,您的每一次支持,我都將銘記于心
總結
以上是生活随笔為你收集整理的Android ANR 实例分析的全部內容,希望文章能夠幫你解決所遇到的問題。
- 上一篇: 串口UART串行总线协议
- 下一篇: (附代码)手写滑动验证码,完整代码开放