Android ANR 分析學習總結

阿新 • • 發佈：2019-02-20

1. 什麼情況下會發生anr

(1). KeyDispatchTimeout(5 seconds) --主要型別按鍵或觸控事件在特定時間內無響應
(2). BroadcastTimeout(10 seconds) --BroadcastReceiver在特定時間內無法處理完成
(3). ServiceTimeout(20 seconds) --小概率型別 Service在特定的時間內無法處理完成

2. KeyDispatchTimeout超時原因

(1). 當前的事件沒有機會得到處理（即UI執行緒正在處理前一個事件，沒有及時的完成或者looper被某種原因阻塞住了）
(2). 當前的事件正在處理，但沒有及時完成

首先要知道事件發生的執行緒，一般來說大多數可能是ui執行緒操作超時，那麼ui執行緒都有哪些呢：
(1). Activity 生命週期
(2). View post 的runnable方法、 handler（MainLooper）的 handleMessage()
(3). Asycktask 的 onPreExecute(), onPostExecute() , onProgressUpdate()方法
(4). Broadcast 的onReceive()
(5). Service
其他原因造成的anr：
(1). 執行緒死鎖
(2). cpu 飢餓

3. 舉例

----- pid 2328 at 2011-12-21 09:36:36 ----- 

Cmd line: system_server

DALVIK THREADS:
(mutexes: tll=0 tsl=0 tscl=0 ghl=0 hwl=0 hwll=0)
"main" prio=5 tid=1 SUSPENDED
  | group="main" sCount=1 dsCount=0 obj=0x4001f180 self=0xce48
  | sysTid=2328 nice=0 sched=0/0 cgrp=default handle=-1345006248
  | schedstat=( 2251911039 10737773873 799 )
  at java.util.ArrayList.size 
(ArrayList.java:~322)   這裡就是案發現場
  at java.util.Collections.sort(Collections.java:1964)
  at com.android.server.IntentResolver.sortResults(IntentResolver.java:334)
  at com.android.server.IntentResolver.queryIntent(IntentResolver.java:305)
  at com.android.server.am.ActivityManagerService.broadcastIntentLocked(ActivityManagerService.java:10288)
  at com.android.server.am.ActivityManagerService.broadcastIntent(ActivityManagerService.java:10478)
  at android.app.ContextImpl.sendStickyBroadcast(ContextImpl.java:736)
  at com.android.server.TelephonyRegistry.broadcastServiceStateChanged(TelephonyRegistry.java:500)
  at com.android.server.TelephonyRegistry.notifyServiceState(TelephonyRegistry.java:267)
  at com.android.internal.telephony.ITelephonyRegistry$Stub.onTransact(ITelephonyRegistry.java:81)
  at android.os.Binder.execTransact(Binder.java:320)
  at com.android.server.SystemServer.init1(Native Method)
  at com.android.server.SystemServer.main(SystemServer.java:854)
  at java.lang.reflect.Method.invokeNative(Native Method)
  at java.lang.reflect.Method.invoke(Method.java:507)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:839)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:597)
  at dalvik.system.NativeStart.main(Native Method)

"Binder Thread #6" prio=5 tid=46 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x406fd210 self=0x44b398
  | sysTid=2592 nice=0 sched=0/0 cgrp=default handle=4321440
  | schedstat=( 131676112 959825670 94 )
  at dalvik.system.NativeStart.run(Native Method)

"Thread-57" prio=5 tid=47 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x406f3068 self=0xd7f80
  | sysTid=2561 nice=10 sched=0/0 cgrp=bg_non_interactive handle=3488688
  | schedstat=( 89258622 34068288100 28 )
  at android.content.res.AssetManager.getStringBlockCount(Native Method)
  at android.content.res.AssetManager.makeStringBlocks(AssetManager.java:256)
  at android.content.res.AssetManager.ensureStringBlocks(AssetManager.java:248)
  at android.content.res.Resources.<init>(Resources.java:160)
  at android.app.ActivityThread.getTopLevelResources(ActivityThread.java:1202)
  at android.app.ActivityThread.getTopLevelResources(ActivityThread.java:1229)
  at android.app.ContextImpl$ApplicationPackageManager.getResourcesForApplication(ContextImpl.java:2372)
  at android.app.ContextImpl$ApplicationPackageManager.getXml(ContextImpl.java:2597)
  at android.content.pm.PackageItemInfo.loadXmlMetaData(PackageItemInfo.java:216)
  at android.app.SearchableInfo.getActivityMetaData(SearchableInfo.java:515)
  at android.server.search.Searchables.buildSearchableList(Searchables.java:215)
  at android.server.search.SearchManagerService.getSearchables(SearchManagerService.java:66)
  at android.server.search.SearchManagerService.access$200(SearchManagerService.java:38)
  at android.server.search.SearchManagerService$BootCompletedReceiver$1.run(SearchManagerService.java:82)

DALVIK THREADS:
"main" prio=5 tid=1 TIMED_WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x400208b8 self=0xcdf0
| sysTid=1732 nice=0 sched=0/0 cgrp=unknown handle=-1345026000
at java.lang.Object.wait(Native Method)
- waiting on <0x4a5ba4b0> (a com.gameloft.robin.DeadLockTraceActivity)  forceWait等待 <0x4a5ba4b0> 
at java.lang.Object.wait(Object.java:326) 
at com.gameloft.robin.DeadLockTraceActivity.forceWait(DeadLockTraceActivity.java:24)
at com.gameloft.robin.DeadLockTraceActivity$1.run(DeadLockTraceActivity.java:18)  匿名內部類1中
at android.os.Handler.handleCallback(Handler.java:587)
at android.os.Handler.dispatchMessage(Handler.java:92)
at android.os.Looper.loop(Looper.java:123)
at android.app.ActivityThread.main(ActivityThread.java:4633)
at java.lang.reflect.Method.invokeNative(Native Method)
at java.lang.reflect.Method.invoke(Method.java:521)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:858)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:616)
at dalvik.system.NativeStart.main(Native Method)

這裡列舉下，執行緒的幾種狀態
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 /
上述處於TIMED_WAIT 。

"PowerManagerService" prio=5 tid=24 MONITOR 在tid為24中
  | group="main" sCount=1 dsCount=0 obj=0x41dd0eb0 self=0x5241b218
  | sysTid=567 nice=0 sched=0/0 cgrp=apps handle=1380038664
  | state=S schedstat=( 6682116007 11324451214 33313 ) utm=450 stm=219 core=1
  at com.android.server.am.ActivityManagerService.broadcastIntent(ActivityManagerService.java:~13045)
  - waiting to lock <0x41a874a0> (a com.android.server.am.ActivityManagerService) held by tid=12 (android.server.ServerThread)  tid 為12的傢伙持有了0x41a874a0資源
  at android.app.ContextImpl.sendBroadcast(ContextImpl.java:1144)
  at com.android.server.power.PowerManagerService$DisplayBlankerImpl.unblankAllDisplays(PowerManagerService.java:3442)
  at com.android.server.power.DisplayPowerState$PhotonicModulator$1.run(DisplayPowerState.java:456)
  at android.os.Handler.handleCallback(Handler.java:800)
  at android.os.Handler.dispatchMessage(Handler.java:100)
  at android.os.Looper.loop(Looper.java:194)
  at android.os.HandlerThread.run(HandlerThread.java:60)

  "Binder_B" prio=5 tid=85 MONITOR 在tid 為85中
  | group="main" sCount=1 dsCount=0 obj=0x42744770 self=0x58329e88
  | sysTid=3700 nice=-20 sched=0/0 cgrp=apps handle=1471424616
  | state=S schedstat=( 1663727513 2044643318 6806 ) utm=132 stm=34 core=1  
  at com.android.server.power.PowerManagerService$DisplayBlankerImpl.toString(PowerManagerService.java:~3449) 
  - waiting to lock <0x41a7e420> (a com.android.server.power.PowerManagerService$DisplayBlankerImpl) held by tid=24 (PowerManagerService)  tid 為24的傢伙持有了0x41a7e420資源
  at java.lang.StringBuilder.append(StringBuilder.java:202)
  at com.android.server.power.PowerManagerService.dump(PowerManagerService.java:3052)
  at android.os.Binder.dump(Binder.java:264)
  at android.os.Binder.onTransact(Binder.java:236)
  at android.os.IPowerManager$Stub.onTransact(IPowerManager.java:373)
  at android.os.Binder.execTransact(Binder.java:351)
  at dalvik.system.NativeStart.run(Native Method)

"android.server.ServerThread" prio=5 tid=12 MONITOR 在tid為12的執行緒中
  | group="main" sCount=1 dsCount=0 obj=0x41a76178 self=0x507837a8
  | sysTid=545 nice=-2 sched=0/0 cgrp=apps handle=1349936616  
  | state=S schedstat=( 15368096286 21707846934 69485 ) utm=1226 stm=310 core=0
  at com.android.server.power.PowerManagerService.isScreenOnInternal(PowerManagerService.java:~2529)
  - waiting to lock <0x41a7e2e8> (a java.lang.Object) held by tid=85 (Binder_B) tid 為85的傢伙持有了0x41a7e2e8資源
  at com.android.server.power.PowerManagerService.isScreenOn(PowerManagerService.java:2522)
  at com.android.server.wm.WindowManagerService.sendScreenStatusToClientsLocked(WindowManagerService.java:7749)
  at com.android.server.wm.WindowManagerService.setEventDispatching(WindowManagerService.java:7628)
  at com.android.server.am.ActivityManagerService.updateEventDispatchingLocked(ActivityManagerService.java:8083)
  at com.android.server.am.ActivityManagerService.wakingUp(ActivityManagerService.java:8077)
  at com.android.server.power.Notifier.sendWakeUpBroadcast(Notifier.java:474)
  at com.android.server.power.Notifier.sendNextBroadcast(Notifier.java:455)
  at com.android.server.power.Notifier.access$700(Notifier.java:62)
  at com.android.server.power.Notifier$NotifierHandler.handleMessage(Notifier.java:600)
  at android.os.Handler.dispatchMessage(Handler.java:107)
  at android.os.Looper.loop(Looper.java:194)
  at com.android.server.ServerThread.run(SystemServer.java:1328)

即
tid=24 等待tid =12 的資源0x41a874a0
tid = 85 等待tid= 24的資源0x41a874a0
tid =12 等待tid =85 的資源0x41a7e2e8
這樣就形成了一個死鎖。

4-01 13:12:11.572 I/InputDispatcher( 220): Application is not responding:Window{2b263310com.android.email/com.android.email.activity.SplitScreenActivitypaused=false}.
    5009.8ms since event, 5009.5ms since waitstarted
    04-0113:12:11.572 I/WindowManager( 220): Input event 
    dispatching timedout sending 
    tocom.android.email/com.android.email.activity.SplitScreenActivity

    04-01 13:12:14.123 I/Process( 220): Sending signal. PID: 21404 SIG: 3---發生ANR的時間和生成trace.txt的時間
    04-01 13:12:14.123 I/dalvikvm(21404):threadid=4: reacting to 
    signal 3 
    ……
    04-0113:12:15.872 E/ActivityManager( 220): ANR in 
    com.android.email(com.android.email/.activity.SplitScreenActivity)
    04-0113:12:15.872 E/ActivityManager( 220): 
    Reason:keyDispatchingTimedOut 
    04-0113:12:15.872 E/ActivityManager( 220): Load: 8.68 / 8.37 / 8.53
    04-0113:12:15.872 E/ActivityManager( 220): CPUusage from 4361ms to 699ms ago ----CPU在ANR發生前的使用情況

    04-0113:12:15.872 E/ActivityManager( 220): 5.5%21404/com.android.email: 1.3% user + 4.1% kernel / faults:
    10 minor
    04-0113:12:15.872 E/ActivityManager( 220): 4.3%220/system_server: 2.7% user + 1.5% kernel / faults: 11
    minor 2 major
    04-0113:12:15.872 E/ActivityManager( 220): 0.9%52/spi_qsd.0: 0% user + 0.9% kernel
    04-0113:12:15.872 E/ActivityManager( 220): 0.5%65/irq/170-cyttsp-: 0% user + 0.5% kernel
    04-0113:12:15.872 E/ActivityManager( 220): 0.5%296/com.android.systemui: 0.5% user + 0% kernel
    04-0113:12:15.872 E/ActivityManager( 220): 100%TOTAL: 4.8% user + 7.6% kernel + 87% iowait
    04-0113:12:15.872 E/ActivityManager( 220): CPUusage from 3697ms to 4223ms later:-- ANR後CPU的使用量
    04-0113:12:15.872 E/ActivityManager( 220): 25%21404/com.android.email: 25% user + 0% kernel / faults: 191 minor
    04-0113:12:15.872 E/ActivityManager( 220): 16% 21603/__eas(par.hakan: 16% user + 0% kernel
    04-0113:12:15.872 E/ActivityManager( 220): 7.2% 21406/GC: 7.2% user + 0% kernel
    04-0113:12:15.872 E/ActivityManager( 220): 1.8% 21409/Compiler: 1.8% user + 0% kernel
    04-0113:12:15.872 E/ActivityManager( 220): 5.5%220/system_server: 0% user + 5.5% kernel / faults: 1 minor
    04-0113:12:15.872 E/ActivityManager( 220): 5.5% 263/InputDispatcher: 0% user + 5.5% kernel
    04-0113:12:15.872 E/ActivityManager( 220): 32%TOTAL: 28% user + 3.7% kernel

注意，中間註釋。
04-0113:12:15.872 E/ActivityManager( 220): 100%TOTAL: 4.8% user + 7.6% kernel + 87% iowait cpu使用率100%
其次，定位在traceview.txt。

-----pid 21404 at 2011-04-01 13:12:14 ----- 
  Cmdline: com.android.email

  DALVIK THREADS:
  (mutexes: tll=0tsl=0 tscl=0 ghl=0 hwl=0 hwll=0)
  "main" prio=5 tid=1NATIVE
  | group="main" sCount=1 dsCount=0obj=0x2aad2248 self=0xcf70
  | sysTid=21404 nice=0 sched=0/0cgrp=[fopen-error:2] 
  handle=1876218976
  atandroid.os.MessageQueue.nativePollOnce(Native Method)
  atandroid.os.MessageQueue.next(MessageQueue.java:119)
  atandroid.os.Looper.loop(Looper.java:110)
  at android.app.ActivityThread.main(ActivityThread.java:3688)
  at java.lang.reflect.Method.invokeNative(Native Method)
  atjava.lang.reflect.Method.invoke(Method.java:507)

  atcom.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866)
  at 
  com.android.internal.os.ZygoteInit.main(ZygoteInit.java:624)
  at dalvik.system.NativeStart.main(Native Method)

可以看到是handler 在等待取訊息。

Android ANR 分析學習總結

1. 什麼情況下會發生anr

2. KeyDispatchTimeout超時原因

3. 舉例

參考

Android ANR 分析學習總結

android anr分析

Android ANR 分析 /data/anr/trace.txt 該文件記錄了產生ANR的函數堆棧可以幫助分析

Android ANR分析實踐（一）：北京×××搭建ANR是什麽、產生的原因及如何避免ANR

Android ANR 分析

Python資料分析學習總結

Android開發新手學習總結(一)——使用Android Studio搭建Android整合開發環境

Android NDK(JNI)學習總結一：Java程式碼中申明native函式-Java呼叫C函式，並在C函式中訪問java類和方法、屬性

Android中Jni學習總結--Jni中列印log資訊

Andriod群英傳-Android Scroll 分析學習筆記

Android Gallery3D原始碼學習總結（三）——Cache快取及資料處理流程

Android Gallery3d原始碼學習總結（二）——繪製流程drawThumbnails

Android MVVM框架學習總結（二）

Windbg dump分析學習總結

Android MVP Pattern 學習總結

[Android] Android RxBus 用法學習總結

看完這篇 Android ANR 分析，就可以和麵試官裝逼了！

Apache Commons Collections 反序列化詳細分析學習總結

Android Kotlin 學習總結(一) 《KAE 優缺點並且深入位元組碼分析工作原理》

Android-ANR總結原理分析

Android ANR 分析學習總結

1. 什麼情況下會發生anr

2. KeyDispatchTimeout超時原因

3. 舉例

參考

相關推薦