android ANR異常分析テクニックまとめ

前言
ANR異常はandroid開発でよく見られる異常の一つで、最近はANR異常を見るために多くの資料が不足しているので、まとめてみましょう.本文は以下のいくつかの角度からANR異常分析を総括する.

1.ANRタイプ

2.ANR発生の原因

3.ANRログソース

4.ANR問題を分析するソケット

1.ANRタイプ
ANRタイプは、エラータイプ別に主にInput(入力イベント)、Broadcast(ブロードキャスト)、Service(サービス)があり、ANRが生成される時間はそれぞれ次のようになります.
を選択します.
フロントアプリケーション
バックグラウンドアプリケーション
Input
5s
5s
Broadcast
10s
6s
Service
20s
200s
上は原生データのみで、各メーカーがデータを修正する可能性があります.また,フロントアプリケーションとバックグラウンドアプリケーションではANRの有無を判断する時間が異なる.このうちInput時間はANR弾枠を直接ポップアップしますが、別の異常はユーザーが操作しなければログだけを印刷し、弾枠は弾けません.
2.ANR発生の原因
ANRを生成する原因の本質は、主スレッドが所定時間内にコードの実行を完了していないことであり、具体的な原因は以下の通りである.

1.複雑なLayout、膨大なforサイクル、IO操作などの時間のかかる操作

2.Binder対端block

3.布団スレッド同期ロックblock

4.Binderがいっぱいになると、プライマリスレッドとSystem_serverプロセス通信

5.システムリソースが得られない(CPU/RAM/IO)

第1点は理解しやすいが、主線の時間がかかりすぎて操作が多すぎる.
第2点は、現在のプロセスのメインスレッドが他のプロセスとBinder通信を行う場合、Binder通信によってメインスレッドが保留され、エンドツーエンドの戻りを待つため、結果的にエンドツーエンドが何らかの原因でずっと戻ってこないため、現在のプロセスのメインスレッドが下に実行できないため、スーパーマーケットでANRが発生する.
第3点は、メインスレッドが他のスレッドと共通ロックされているが、ロックされていないため、タイムアウトし、ANRが発生することを意味する.
4つ目はメインスレッドとSystem_サーバプロセスは、他のスレッドまたは他のプロセスがSystem_と通信するため、Binder通信を行います.serverプロセスの間にはBinder通信が多すぎて、Binderプールをいっぱいにして、メインスレッドのBinder通信がずっと処理できなくて、タイムアウトしてANRを生成します.
第5のポイントは、システムリソースが緊張するため、CPU占有率が高すぎる、負荷が大きすぎる、IO操作が多すぎるため、メインスレッドがCPUタイムスライスなどのシステムリソースを得ることができず、ANRが発生する.
このうち、前の4つは分析がよく、ログを通じて手がかりを見つけて解決することができますが、5つ目の位置決めは難しいです.5つ目のANRはソフトウェアの問題ではなく、複雑な状況にあるからです.
3.ANRログソース
サードパーティのデータが報告されたり、テスト担当者がテスト中にログをキャプチャしたりした場合は、ログを直接表示できますが、問題が発見されたり再現されたりした場合は、次の方法でログを取得できます.
3.1 traces.txt
ANRはこのログを優先的に見る、AMSはANRが発生したときにdump関連プロセス(ANRのプロセス、systemserver、mediaserver、surfaceFingerなど)の現在のスタックをtracesに送る.txt.注意しなければならないのはtxtは、タイムアウト後(例えばinputタイムアウトが5 s後)のsnapshotをキャプチャし、blockの点をリアルに反応させるとは限らない.マスタースレッドを捕まえてblockがなく、idleにいる場合もあります.
取得するtxtの方式:adb pull/data/anr/traces.txt
3.2 applogcat-log
私たちのlogcat情報はここに印刷され、中には多くのスタック情報があり、日付によって最新のログを取り出します.取得applogcat-log方式:adb pull/data/log/android_logs
3.3 dropbox
異なるエラーメッセージログが記録され、ログ名のフォーマットはAA_です[email protected],AAはプロセス名,BBは例外タイプ,CCはシステム[email protected]は、ANR異常を表すログファイルで、自分の対応する時間とプロセスのログ情報を見つければよい.このログは手がかりとして使用できます.
取得方法:adb pull/data/system/dropbox
4.ANR問題を分析する方法
4.1メインスレッドでの時間のかかる操作
これは普通にチェックしやすいですが、(この公式アプリは今でも普通にはないでしょう...)、コードが見えない場合は、ログを見てtracesを開くことができます.txtファイル、最初の行が表示されます.

----- pid 13250 at 2018-01-01 23:56:09 -----

このプロセス13250を表すログはここから始まります.一般的にtracesです.txtファイルの最初のプロセスはANRが存在するプロセスが発生し、次に下を見て、メインスレッドのログを見つけて、栗を挙げます.

"main" prio=5 tid=1 Native
  | group="main" sCount=1 dsCount=0 obj=0x7425caf8 self=0xb4827800
  | sysTid=671 nice=0 cgrp=default sched=0/0 handle=0xb6febbec
  | state=S schedstat=( 0 0 0 ) utm=1853 stm=50 core=2 HZ=100
  | stack=0xbe7bd000-0xbe7bf000 stackSize=8MB
  | held mutexes=
  kernel: (couldn't read /proc/self/task/671/stack)
  native: #00 pc 000133cc  /system/lib/libc.so (syscall+28)
  native: #01 pc 000a9a83  /system/lib/libart.so (art::ConditionVariable::Wait(art::Thread*)+82)
  native: #02 pc 001b16f1  /system/lib/libart.so (art::JNI::NewString(_JNIEnv*, unsigned short const*, int)+640)
  native: #03 pc 00075887  /system/lib/libandroid_runtime.so (???)
  native: #04 pc 008570ab  /data/dalvik-cache/arm/system@[email protected] (Java_android_database_CursorWindow_nativeGetString__JII+110)
  at android.database.CursorWindow.nativeGetString(Native method)
  at android.database.CursorWindow.getString(CursorWindow.java:438)
  at android.database.AbstractWindowedCursor.getString(AbstractWindowedCursor.java:51)
  at android.database.CursorWrapper.getString(CursorWrapper.java:114)
  at com.android.settings.ApnSettings.fillList(ApnSettings.java:259)
  at com.android.settings.ApnSettings.onResume(ApnSettings.java:208)
  at android.app.Fragment.performResume(Fragment.java:2096)
  at android.app.FragmentManagerImpl.moveToState(FragmentManager.java:928)
  at android.app.FragmentManagerImpl.moveToState(FragmentManager.java:1067)
  at android.app.FragmentManagerImpl.moveToState(FragmentManager.java:1049)
  at android.app.FragmentManagerImpl.dispatchResume(FragmentManager.java:1879)
  at android.app.Activity.performResume(Activity.java:6113)
  at android.app.ActivityThread.performResumeActivity(ActivityThread.java:3015)
  at android.app.ActivityThread.handleResumeActivity(ActivityThread.java:3061)
  at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:2415)
  at android.app.ActivityThread.access$800(ActivityThread.java:151)
  at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1313)
  at android.os.Handler.dispatchMessage(Handler.java:102)
  at android.os.Looper.loop(Looper.java:135)
  at android.app.ActivityThread.main(ActivityThread.java:5345)
  at java.lang.reflect.Method.invoke!(Native method)
  at java.lang.reflect.Method.invoke(Method.java:372)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:947)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:742)

このログでは、最初の行の「main」を見ると、これがメインスレッドであり、mainはスレッド名であることがわかります.そしてApnSettingsからJAvaではfillListという可能性のある時間のかかる操作メインスレッド処理が見られる場所にOnResumeとOnReceiveがあります.呼び出しスタックはここで終わりますから.また,コードにはHandlerThreadを用いてこの操作を非同期で処理する箇所があり,OnResumeとOnReceiveの両方をHandlerThreadに入れることを参考にすることができる.
4.2 Binderによってブロックされる

 "main" prio=5 tid=1 Native
  | group="main" sCount=1 dsCount=0 obj=0x73ee6470 self=0xb4d76500
  | sysTid=22831 nice=0 cgrp=default sched=0/0 handle=0xb6f4bc00
  | state=S schedstat=( 0 0 0 ) utm=22 stm=22 core=0 HZ=100
  | stack=0xbe283000-0xbe285000 stackSize=8MB
  | held mutexes=
  native: #00 pc 000410ac  /system/lib/libc.so (__ioctl+8)
  native: #01 pc 000477e5  /system/lib/libc.so (ioctl+14)
  native: #02 pc 0001e7c5  /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+132)
  native: #03 pc 0001ee17  /system/lib/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+38)
  native: #04 pc 0001efcd  /system/lib/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+124)
  native: #05 pc 00019fb7  /system/lib/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+30)
  native: #06 pc 00086de9  /system/lib/libandroid_runtime.so (???)
  native: #07 pc 00d94629  /data/dalvik-cache/arm/system@[email protected] (Java_android_os_BinderProxy_transactNative__ILandroid_os_Parcel_2Landroid_os_Parcel_2I+140)
  at android.os.BinderProxy.transactNative(Native method)
  at android.os.BinderProxy.transact(Binder.java:503)
  at android.net.INetworkPolicyManager$Stub$Proxy.getNetworkPolicies(INetworkPolicyManager.java:410)
  at android.net.NetworkPolicyManager.getNetworkPolicies(NetworkPolicyManager.java:174)
  at com.android.settings.net.NetworkPolicyEditor.read(NetworkPolicyEditor.java:57)
  at com.android.settings.DataUsageSummary.onCreate(DataUsageSummary.java:361)
  at android.app.Fragment.performCreate(Fragment.java:2202)
  at android.app.FragmentManagerImpl.moveToState(FragmentManager.java:942)
  at android.app.FragmentManagerImpl.moveToState(FragmentManager.java:1148)
  at android.app.BackStackRecord.run(BackStackRecord.java:793)
  at android.app.FragmentManagerImpl.execPendingActions(FragmentManager.java:1535)
  at android.app.FragmentManagerImpl.executePendingTransactions(FragmentManager.java:562)
  at com.android.settings.SettingsActivity.switchToFragment(SettingsActivity.java:1084)
  at com.android.settings.SettingsActivity.onCreate(SettingsActivity.java:657)
  at android.app.Activity.performCreate(Activity.java:6251)
  at android.app.Instrumentation.callActivityOnCreate(Instrumentation.java:1110)
  at android.app.ActivityThread.performLaunchActivity(ActivityThread.java:2370)
  at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:2477)
  at android.app.ActivityThread.-wrap11(ActivityThread.java:-1)
  at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1345)
  at android.os.Handler.dispatchMessage(Handler.java:102)
  at android.os.Looper.loop(Looper.java:148)
  at android.app.ActivityThread.main(ActivityThread.java:5438)
  at java.lang.reflect.Method.invoke!(Native method)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:762)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:652)

ホストは、NetworkPolicyManagerが呼び出されたことをログから確認します.getNetworkPolicies、それからBinder通信を行って、それからスタックを呼び出してここで終了して、対端blockだと推測して、Binder通信の両端の方法名は一致しているので、更に現在のログでgetNetworkPoliciesを検索して、対端を見つけることができます:

"Binder_4" prio=5 tid=56 Blocked
  | group="main" sCount=1 dsCount=0 obj=0x1321a0a0 self=0xad31e200
  | sysTid=2491 nice=0 cgrp=default sched=0/0 handle=0x9fd00930
  | state=S schedstat=( 0 0 0 ) utm=46441 stm=46582 core=1 HZ=100
  | stack=0x9fc04000-0x9fc06000 stackSize=1014KB
  | held mutexes=
  at com.android.server.net.NetworkPolicyManagerService.getNetworkPolicies(NetworkPolicyManagerService.java:1696)
  - waiting to lock <0x07439315> (a java.lang.Object) held by thread 35
  at android.net.INetworkPolicyManager$Stub.onTransact(INetworkPolicyManager.java:145)
  at android.os.Binder.execTransact(Binder.java:453

Tid=35の人にロック(0 x 074393315)を取られた場合、tid=35が誰なのかを見続けるには、2つの方法があります.

検索tid=35

0 0 x 074393315検索-locked<0 x 074393315>(a java.lang.Object)

を検索

"NetworkPolicy" prio=5 tid=35 TimedWaiting
  | group="main" sCount=1 dsCount=0 obj=0x12d98940 self=0x9f91f700
  | sysTid=2415 nice=0 cgrp=default sched=0/0 handle=0xa0f33930
  | state=S schedstat=( 0 0 0 ) utm=7681 stm=7783 core=0 HZ=100
  | stack=0xa0e31000-0xa0e33000 stackSize=1038KB
  | held mutexes=
  at java.lang.Object.wait!(Native method)
  - waiting on <0x02580c1b> (a java.lang.Object)
  at java.lang.Thread.parkFor$(Thread.java:1220)
  - locked <0x02580c1b> (a java.lang.Object)
  at sun.misc.Unsafe.park(Unsafe.java:299)
  at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2053)
  at java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:372)
  at com.android.server.NativeDaemonConnector$ResponseQueue.remove(NativeDaemonConnector.java:634)
  at com.android.server.NativeDaemonConnector.executeForList(NativeDaemonConnector.java:426)
  at com.android.server.NativeDaemonConnector.execute(NativeDaemonConnector.java:345)
  at com.android.server.NativeDaemonConnector.execute(NativeDaemonConnector.java:340)
  at com.android.server.NetworkManagementService.setInterfaceQuota(NetworkManagementService.java:1712)
  - locked <0x0b0f91b8> (a java.lang.Object)
  at com.android.server.net.NetworkPolicyManagerService.setInterfaceQuota(NetworkPolicyManagerService.java:2421)
  at com.android.server.net.NetworkPolicyManagerService.updateNetworkRulesLocked(NetworkPolicyManagerService.java:1232)
  at com.android.server.net.NetworkPolicyManagerService$14.onReceive(NetworkPolicyManagerService.java:1060)
  - locked <0x07439315> (a java.lang.Object)
  at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:881)
  at android.os.Handler.handleCallback(Handler.java:739)
  at android.os.Handler.dispatchMessage(Handler.java:95)
  at android.os.Looper.loop(Looper.java:148)
  at android.os.HandlerThread.run(HandlerThread.java:61)

NetworkPolicyはNativeDaemonConnectorとnetd通信(setInterfaceQuota)を通じてlogを結合してANRが発生する前後の印刷を見ることができます.

06-19 15:29:00.997  1235  1270 I am_anr  : [0,22831,com.android.settings,818429509,Input dispatching timed out (Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)]
  06-19 15:29:05.683  1235  2415 E NetdConnector: NDC Command {55445 bandwidth setiquota seth_w0 9223372036854775807} took too long (4755ms
  06-19 15:29:05.723  1235  2491 I dvm_lock_sample: [system_server,1,Binder_4,4919,NetworkPolicyManagerService.java,1696,-,1056,100]

eventslogからsettingには2回連続したANRが現れ,コンテキストには上記のようなdvm_があることも分かった.lock_sample NetworkPolicyManagerService関連のアラート.したがって,15:28の今回のANRは有用なスタックを打ち出さなかったが,この2回のANRの原因はいずれもnetdのcommandが時間がかかりすぎたため(メインスレッドの呼び出し経路に必然的なblockが存在する)であり,netdが修正できない可能性がある場合(少なくともアプリケーション層は修正できない)は,blockが存在する可能性のある操作を非UIスレッドに置くしかないと推測できる.
4.3メインスレッドがスレッドに同期してロックされて、ANRになる
この問題は、メインスレッドのログに次の文が表示されている限り、上に下がったBinderエンドblockの例と似ています.

 waiting to lock <0x07439315> (a java.lang.Object) held by thread 35

メインスレッドがロックを待っていることを説明し、held by thread 35は同期ロックがスレッド番号35によって保持されていることを識別し、このスレッド番号または0 x 074393315を検索して、このスレッドが何をしているかを見て、問題の原因を見つけることができます.
4.4システム資源の緊張によるANR

04-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
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    ======later   
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

上記のログには、次の3行があります.

04-01 13:12:14.123 I/Process( 220): Sending signal. PID:21404 SIG:3-ANRが発生する時間とtraceが生成する.txtの時間

04-013:12:15.872 E/ActivityManager(220):CPU usage from 4361 ms to 699 ms ago----CPUのANR発生前の使用状況

04-013:12:15.872 E/ActivityManager(220):100%TOTAL:4.8%user+7.6%kernel+87%iowait 04-013:12:15.872 E/ActivityManager(220):CPU usage from 3697 ms to 4223 ms later:--ANR後CPUの使用量

このログからCPU使用率が高く、IO操作の割合が大きい(87%iowait)ことでシステムリソースが緊張していることがわかりますが、ANRが発生する可能性が高いと推測するしかありません.このCPU統計は時間帯であり、リアルタイムではないので、具体的にはログで他の手がかりを探して問題を特定する必要があります.