Android教程網
  1. 首頁
  2. Android 技術
  3. Android 手機
  4. Android 系統教程
  5. Android 游戲
 Android教程網 >> Android技術 >> 關於Android編程 >> Android ANR分析

Android ANR分析

編輯:關於Android編程

前言

ANR即Application Not Responding,顧名思義就是應用程序無響應。在Android中,一般情況下,四大組件均是工作在主線程中的,Android中的Activity Manager和Window Manager會隨時監控應用程序的響應情況,如果因為一些耗時操作(網絡請求或者IO操作)造成主線程阻塞一定時間(例如造成5s內不能響應用戶事件或者BroadcastReceiver的onReceive方法執行時間超過10s),那麼系統就會顯示ANR對話框提示用戶對應的應用處於無響應狀態。

雖然每個程序員都不想ANR發生在自己的頭上,因此,你需要嚴格遵守Google提供的一系列建議(看這裡),簡單總結就是以下兩點:

1. 不要讓主線程干耗時的工作
2. 不要讓其他線程阻塞主線程的執行

因此,要盡量保證主線程執行工作干淨利落,一個消息循環執行時間最好不超過100ms到200ms,對於一些髒活累活可以交給AsyncTask、HandlerThread、IntentService或者另外起的新線程來完成,這樣應用程序就能夠及時響應用戶的操作而不會給用戶帶來卡頓的感覺。

ANR分析

一般應用程序在發布之前最好對新增的功能通過Systrace+TraceView進行性能測試,這樣能夠及時發現程序當中的耗時操作,對於一些可能引起ANR的風險做到提前規避。如果你是一個完美主義者,你也可以使用StrictMode來發現並干掉在你主線程中存在的一些磁盤IO、網絡操作或者mysql" target="_blank" title="MySQL知識庫">數據庫讀寫等耗時代碼,但是我個人覺得要完全避免在主線程進行這些操作還是不太現實,即使做到了也可能會造成應用程序的代碼結構比較糟糕。
即使程序員在自己的環境中對代碼進過了一系列的性能測試,到用戶手中還是有中招的風險,畢竟再高效率的代碼還是要時間來執行,而且不同手機性能差距還是很明顯。如果你不幸中招,那麼可以采用以下的方法來進行簡單的分析。

導出trace文件

如果ANR發生,對應的應用會收到SIGQUIT異常終止信號,dalvik虛擬機就會自動在/data/anr/目錄下生成trace.txt文件,這個文件記錄了在發生ANR時刻系統各個線程的執行狀態,獲取這個文件是不需要root權限的,因此首先需要做的就是通過adb pull命令將這個文件導出並等待分析。

trace文件格式解析

導出trace文件後,可以看到類似於如下的文件內容:

----- pid 901 at 2015-11-28 14:38:34 -----
Cmd line: system_server

JNI: CheckJNI is off; workarounds are off; pins=6; globals=2154 (plus 409 weak)

DALVIK THREADS:
(mutexes: tll=0 tsl=0 tscl=0 ghl=0)

"main" prio=5 tid=1 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x415a4e88 self=0x414c48d8
  | sysTid=901 nice=-2 sched=0/0 cgrp=apps handle=1073926484
  | state=S schedstat=( 303590361913 618664734427 651535 ) utm=19466 stm=10893 core=0
  #00  pc 00021914  /system/lib/libc.so (epoll_wait+12)
  #01  pc 0001065f  /system/lib/libutils.so (android::Looper::pollInner(int)+98)
  #02  pc 00010889  /system/lib/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+92)
  #03  pc 0006b771  /system/lib/libandroid_runtime.so (android::NativeMessageQueue::pollOnce(_JNIEnv*, int)+22)
  #04  pc 0002034c  /system/lib/libdvm.so (dvmPlatformInvoke+112)
  #05  pc 00050fcf  /system/lib/libdvm.so (dvmCallJNIMethod(unsigned int const*, JValue*, Method const*, Thread*)+398)
  #06  pc 00000214  /dev/ashmem/dalvik-jit-code-cache (deleted)
  at android.os.MessageQueue.nativePollOnce(Native Method)
  at android.os.MessageQueue.next(MessageQueue.java:138)
  at android.os.Looper.loop(Looper.java:196)
  at com.android.server.ServerThread.initAndLoop(SystemServer.java:1174)
  at com.android.server.SystemServer.main(SystemServer.java:1271)
  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:878)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:694)
  at dalvik.system.NativeStart.main(Native Method)

首先需要了解這些參數表示的意義,我們挑其中關鍵的幾個說明:

  • 第一二行

    ----- pid 901 at 2015-11-28 14:38:34 -----
    Cmd line: system_server
    

    說明了發生ANR的進程id、時間和進程名稱。

  • 後面三行是線程的基本信息

    JNI: CheckJNI is off; workarounds are off; pins=6; globals=2154 (plus 409 weak)
    
    DALVIK THREADS:
    (mutexes: tll=0 tsl=0 tscl=0 ghl=0)
    

    其中tll、tsl、tscl、ghl、hwl、hwll分別對應:thread list lock, thread suspend lock, thread suspend count lock, gc heap lock, heap worker lock和heap worker list lock。

  • main prio=5 tid=1 NATIVE說明了線程名稱、線程的優先級、線程鎖id和線程狀態。線程名稱是啟動線程的時候手動指明的,這裡的main標識是主線程,是Android自動設定的一個線程名稱,如果是自己手動創建的線程,一般會被命名成“Thread-xx”的格式,其中xx是線程id,它只增不減不會被復用;注意這其中的tid不是線程的id,它是一個在Java虛擬機中用來實現線程鎖的變量,隨著線程的增減,這個變量的值是可能被復用的;最後線程的狀態還分為如下幾種

    狀態 值 說明 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_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

    特別說明一下MONITOR狀態和SUSPEND狀態,MONITOR狀態一般是類的同步塊或者同步方法造成的,SUSPENDED狀態在debugger的時候會出現,可以用來區別是不是真的是用戶正常操作跑出了ANR。

  • 後面一行

    | group="main" sCount=1 dsCount=0 obj=0x415a4e88 self=0x414c48d8
    

    group是線程組名稱。sCount是此線程被掛起的次數,dsCount是線程被調試器掛起的次數,當一個進程被調試後,sCount會重置為0,調試完畢後sCount會根據是否被正常掛起增長,但是dsCount不會被重置為0,所以dsCount也可以用來判斷這個線程是否被調試過。obj表示這個線程的Java對象的地址,self表示這個線程本身的地址。

  • 此後是線程的調度信息

    sysTid=901 nice=-2 sched=0/0 cgrp=apps handle=1073926484
    

    sysTid是Linux下的內核線程id,nice是線程的調度優先級,sched分別標志了線程的調度策略和優先級,cgrp是調度屬組,handle是線程的處理函數地址。

  • 然後是線程當前上下文信息

    state=S schedstat=( 303590361913 618664734427 651535 ) utm=19466 stm=10893 core=0
    

    state是調度狀態;schedstat從 /proc/[pid]/task/[tid]/schedstat讀出,三個值分別表示線程在cpu上執行的時間、線程的等待時間和線程執行的時間片長度,有的android內核版本不支持這項信息,得到的三個值都是0;utm是線程用戶態下使用的時間值(單位是jiffies);stm是內核態下的調度時間值;core是最後執行這個線程的cpu核的序號。

最後就是這個線程的調用棧信息。

通過分析trace文件得到ANR信息

通過上面分析,可以看到trace文件的頭部就包含了很多與該線程相關的信息,但是並不是每個信息我們都必須弄懂,排查ANR的時候只需要找到其中關鍵的幾個信息即可。一般可以通過以下幾個簡單的方法來判斷。

trace文件頂部的線程一般是ANR的元凶

這是一個簡單的方法,但是大部分情況下都適用,可以通過這個方法來快速判斷是否是自己的應用造成了本次ANR。說明以下,並不是trace文件包含的應用就一定是造成ANR的幫凶,應用出現在trace文件中,只能說明出現ANR的時候這個應用進程還活著,trace文件的頂部則是觸發ANR的應用信息。因此,如果你的應用出現在了trace文件的頂部,那麼很有可能是因為你的應用造成了ANR,否則是你的應用造成ANR的可能性不大,但是具體是不是還需要進一步分析。例如:

    ----- pid 1182 at 2015-11-26 01:53:34 -----
    Cmd line: system_server

    JNI: CheckJNI is off; workarounds are off; pins=5; globals=2982 (plus 135 weak)

    DALVIK THREADS:
    (mutexes: tll=0 tsl=0 tscl=0 ghl=0)

    "main" prio=5 tid=1 NATIVE
      | group="main" sCount=1 dsCount=0 obj=0x420a0e58 self=0x4208f918
      | sysTid=1182 nice=-2 sched=0/0 cgrp=apps handle=1074594132
      | state=S schedstat=( 211672310629 149959255867 472114 ) utm=13047 stm=8120 core=1
      #00  pc 000218b8  /system/lib/libc.so (epoll_wait+12)
      ...
     at android.os.MessageQueue.nativePollOnce(Native Method)
      at android.os.MessageQueue.next(MessageQueue.java:138)
      at android.os.Looper.loop(Looper.java:123)
      at com.android.server.ServerThread.initAndLoop(SystemServer.java:1213)
      at com.android.server.SystemServer.main(SystemServer.java:1317)
      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:793)
      at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:609)
      at dalvik.system.NativeStart.main(Native Method)

      ...

    ----- end 1182 -----

     ----- pid 18927 at 2015-11-26 01:53:34 -----
    Cmd line: com.android.example

    JNI: CheckJNI is off; workarounds are off; pins=0; globals=465 (plus 984 weak)

    DALVIK THREADS:
    (mutexes: tll=0 tsl=0 tscl=0 ghl=0)

    "main" prio=5 tid=1 NATIVE
      | group="main" sCount=1 dsCount=0 obj=0x420a0e58 self=0x4208f918
      | sysTid=18927 nice=-6 sched=0/0 cgrp=apps handle=1074594132
      | state=S schedstat=( 7748840431407 1615931922290 9994018 ) utm=712375 stm=62509 core=1
      #00  pc 00020704  /system/lib/libc.so (__ioctl+8)
      #01  pc 0002cfa3  /system/lib/libc.so (ioctl+14)
      #02  pc 0001d3ed  /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+140)
      #03  pc 0001d8d7  /system/lib/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+42)
      #04  pc 0001dadf  /system/lib/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+118)
      #05  pc 00019791  /system/lib/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+30)
      ...
      #23  pc 00000d80  /system/bin/app_process
      at android.os.BinderProxy.transact(Native Method)
      at android.app.IAlarmManager$Stub$Proxy.set(IAlarmManager.java:154)
      at android.app.AlarmManager.setImpl(AlarmManager.java:369)
      at android.app.AlarmManager.setRepeating(AlarmManager.java:258)
      at android.os.Handler.handleCallback(Handler.java:733)
      at android.os.Handler.dispatchMessage(Handler.java:95)
      at android.os.Looper.loop(Looper.java:136)
      at android.app.ActivityThread.main(ActivityThread.java:5072)
      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:793)
      at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:609)
      at dalvik.system.NativeStart.main(Native Method)

雖然應用com.android.example出現在了trace文件中,但是在ANR的時候它在通過IPCThread在進行進程間通信,而此次ANR發生於system_server獲取用戶事件的native方法裡面,並不是我們的應用造成了ANR。又例如下面的trace文件頂部內容為:

    ----- pid 13406 at 2015-11-27 11:46:14 -----
    Cmd line: com.android.example

    JNI: CheckJNI is off; workarounds are off; pins=0; globals=536 (plus 102 weak)

    DALVIK THREADS:
    (mutexes: tll=0 tsl=0 tscl=0 ghl=0)

    "main" prio=5 tid=1 SUSPENDED
      | group="main" sCount=1 dsCount=0 obj=0x41795e58 self=0x416b58b0
      | sysTid=13406 nice=-6 sched=0/0 cgrp=apps handle=1074557268
      | state=S schedstat=( 2352435524847 736727917292 2633566 ) utm=213075 stm=22168 core=1
      at java.lang.String.(String.java:~261)
      at java.util.zip.ZipEntry.(ZipEntry.java:392)
      at java.util.zip.ZipFile.readCentralDir(ZipFile.java:414)
      at java.util.zip.ZipFile.(ZipFile.java:151)
      at java.util.zip.ZipFile.(ZipFile.java:123)
      at com.android.example.Utility.isValideFile(Utility.java:2700)
      at com.android.example.Test.getPath(Test.java:243)
      at com.android.example.Test$1.run(Test.java:531)
      at android.os.Handler.handleCallback(Handler.java:733)
      at android.os.Handler.dispatchMessage(Handler.java:95)
      at android.os.Looper.loop(Looper.java:136)
      at android.app.ActivityThread.main(ActivityThread.java:5050)
      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:807)
      at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:623)
      at dalvik.system.NativeStart.main(Native Method)
      ...

這種情況說明ANR發生於com.android.example應用中,而且指明了ANR發生時代碼的執行位置,這種情況十有八九就是我們應用程序的問題,之後就需要通過這個trace文件指明的路徑來對代碼進行排查。

注意死鎖和等待

雖然說ANR一般情況是由於讓主線程做了很多耗時的操作,但是死鎖或者主線程等待也是ANR高發的原因,例如如下的trace:

----- pid 9436 at 2015-11-28 21:30:41 -----
Cmd line: com.example.yxz.myapplication

JNI: CheckJNI is off; workarounds are off; pins=0; globals=277

DALVIK THREADS:
(mutexes: tll=0 tsl=0 tscl=0 ghl=0)

"main" prio=5 tid=1 MONITOR
  | group="main" sCount=1 dsCount=0 obj=0x415a4e88 self=0x414c48d8
  | sysTid=9436 nice=0 sched=0/0 cgrp=apps handle=1073926484
  | state=S schedstat=( 671264662 337280259 1005 ) utm=53 stm=14 core=0
  at com.example.yxz.myapplication.performancetest.WaitANR$InnerMonitorClass.TimeConsumeFunc(WaitANR.java:~48)
  - waiting to lock <0x447a5670>  held by tid=11 (Thread-14208)
  at com.example.yxz.myapplication.performancetest.WaitANR$2.run(WaitANR.java:32)
  at android.os.Handler.handleCallback(Handler.java:733)
  at android.os.Handler.dispatchMessage(Handler.java:95)
  at android.os.Looper.loop(Looper.java:212)
  at android.app.ActivityThread.main(ActivityThread.java:5135)
  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:878)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:694)
  at dalvik.system.NativeStart.main(Native Method)

....

"Thread-14208" prio=10 tid=11 TIMED_WAIT
  | group="main" sCount=1 dsCount=0 obj=0x447a4b98 self=0x78296bb8
  | sysTid=9955 nice=-8 sched=0/0 cgrp=apps handle=2015978016
  | state=S schedstat=( 946045 640869 1 ) utm=0 stm=0 core=2
  at java.lang.VMThread.sleep(Native Method)
  at java.lang.Thread.sleep(Thread.java:1013)
  at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:331)
  at com.example.yxz.myapplication.performancetest.WaitANR$InnerMonitorClass.TimeConsumeFunc(WaitANR.java:48)
  at com.example.yxz.myapplication.performancetest.WaitANR$1.run(WaitANR.java:20)
  at java.lang.Thread.run(Thread.java:841)

從trace文件可以看出,發生ANR的主線程正處於monitor狀態,也就是它在等待一個synchronized塊或者方法,但是目前這個monitor正在被tid=11的線程持有,所以造成了主線程被阻塞,從而發生了ANR。死鎖的分析也是類似,發生死鎖的線程一般處於MONITOR狀態或者WAIT狀態,等待其他進程的鎖或者monitor,而其他進程又在等待另外線程的鎖或者monitor,一直這樣依賴下去,直到形成一個環。

結束

以上都是自己總結,歡迎提出意見和拍磚!

  1. 上一頁:
  2. 下一頁:
熱門文章
閱讀排行版
Copyright © Android教程網 All Rights Reserved