ANR

围巾🧣 2020年06月06日 676次浏览

ANR

概念

ANR（Application Not responding），是指应用程序未响应，Android系统对于一些事件需要在一定的时间范围内完成，如果超过预定时间能未能得到有效响应或者响应时间过长，都会造成ANR

场景

  • Service Timeout
  • BroadcastQueue Timeout
  • ContentProvider Timeout
  • InputDispatching Timeout

Timeout时长

  • 对于前台服务，则超时为SERVICE TIMEOUT = 20s；

  • 对于后台服务，则超时为SERVICE BACKGROUND TIMEOUT = 200s

  • 对于前台广播，则超时为BROADCAST FG TIMEOUT= 10s；

  • 对于后台广播，则超时为BROADCAST BG TIMEOUT= 60s；

  • ContentProvider超时为CONTENT PROVIDER PUBLISH TIMEOUT=
    10s；

  • InputDispatching Timeout：输入事件分发超时5s，包括按键和触摸事件。

    注意事项：Input的超时机制与其他的不同，对于input来说即便某次事件执行时间超过timeout时长，只要用户后续在没有再生成输入事件，则不会触发ANR

超时检测机制

  1. Service超时检测机制：
    • 超过一定时间没有执行完相应操作来触发移除延时消息，则会触发anr；
  2. BroadcastReceiver超时检测机制：
    • 有序广播的总执行时间超过2 * receiver个数 * timeout时长，则会触发anr；有序广播的某一个receiver执行过程超过timeout时长，则会触发anr；
  3. 另外：
    • 对于Service，Broadcast，Input发生ANR之后，最终都会调用AMS.appNotResponding（新版为AppError的方法）；
    • 对于provider，在其进程启动时publish过程可能会出现ANR，则会直接杀进程以及清理相应信息，而不会弹出ANR的对话框

前台与后台ANR（了解）

  • 前台ANR：用户能感知，比如拥有前台可见的activity的进程，或者拥有前台通知的fg- service的进程，此时发生ANR对用户体验影响比较大，需要弹框让用户决定是否退出还是等待
  • 后台ANR:，只抓取发生无响应进程的trace，也不会收集CPU信息，并且会在后台直接杀掉该无响应的进程，不会弹框提示用户

ANR分析

  1. 前台ANR发生后，系统会马上去抓取现场的信息，用于调试分析，收集的信息如下：
    • 将am anr信息输出到EventLog，也就是说ANR触发的时间点最接近的就是EventLog中输出的am_anr信息
    • 收集以下重要进程的各个线程调用栈trace信息，保存在data/anr/traces.txt文件
      • 当前发生ANR的进程，system server进程以及所有persistent进程
      • audioserver，cameraserver，mediaserver，surfaceflinger等重要的native进程
      • CPU使用率排名前5的进程
    • 将发生ANR的reason以及CPU使用情况信息输出到main log
    • 将traces文件和CPU使用情况信息保存到dropbox.即data/system/dropbox目录
    • 对用户可感知的进程则弹出ANR对话框告知用户，对用户不可感知的进程发生ANR则直接杀掉
  2. 分析步骤
    • 定位发生ANR时间点
    • 查看trace信息
    • 分析是否有耗时的message，binder调用，锁的竞争，CPU资源的抢占
    • 结合具体的业务场景的上下文来分析

如何避免ANR发生

  1. 主线程尽量只做UI相关的操作，避免耗时操作，比如过度复杂的UI绘制，网络操作，文件IO操作；
  2. 避免主线程跟工作线程发生锁的竞争，减少系统耗时binder的调用，谨慎使用sharePreference，注意主线程执行provider query操作

总之，尽可能减少主线程的负载，让其空闲待命，以期可随时响应用户的操作

trace.txt文件解读⚔

  1. 人为的收集trace.txt的命令
    adb shel1 kill-3 888//可指定进程pid
    执行完该命令后traces信息的结果保存到文件/data/anr/traces.txt

  2. trace文件解读

    
----- pid 12541 at 2020-06-05 19:03:28 -----
Cmd line: com.sparetimeforu.android.sparetimeforu
Build fingerprint: 'lge/joan_lgu_kr/joan:8.0.0/OPR1.170623.026/190141546d20e:user/release-keys'
ABI: 'arm64'
Build type: optimized
Zygote loaded classes=4968 post zygote classes=1389
Intern table: 48085 strong; 292 weak
JNI: CheckJNI is on; globals=765 (plus 46 weak)
Libraries: /data/app/com.sparetimeforu.android.sparetimeforu-pqnddOUFZ9BFqr48mFDS0A==/lib/arm64/libBaiduMapSDK_base_v5_3_0.so /data/app/com.sparetimeforu.android.sparetimeforu-pqnddOUFZ9BFqr48mFDS0A==/lib/arm64/libBaiduMapSDK_map_v5_3_0.so /data/app/com.sparetimeforu.android.sparetimeforu-pqnddOUFZ9BFqr48mFDS0A==/lib/arm64/liblocSDK7b.so /system/lib64/libandroid.so /system/lib64/libcompiler_rt.so /system/lib64/libjavacrypto.so /system/lib64/libjnigraphics.so /system/lib64/liblgruntime.so /system/lib64/libmedia_jni.so /system/lib64/libsoundpool.so /system/lib64/libwebviewchromium_loader.so libjavacore.so libopenjdk.so (13)
Heap: 63% free, 2MB/6MB; 41821 objects
Dumping cumulative Gc timings
Start Dumping histograms for 2 iterations for concurrent copying
ProcessMarkStack:	Sum: 27.283ms 99% C.I. 5.275ms-22.008ms Avg: 13.641ms Max: 22.008ms
VisitConcurrentRoots:	Sum: 5.977ms 99% C.I. 1.630ms-4.323ms Avg: 2.988ms Max: 4.347ms
FlipThreadRoots:	Sum: 4.350ms 99% C.I. 0.004ms-4.307ms Avg: 2.175ms Max: 4.346ms
ScanImmuneSpaces:	Sum: 3.398ms 99% C.I. 0.824ms-2.574ms Avg: 1.699ms Max: 2.574ms
EnqueueFinalizerReferences:	Sum: 1.633ms 99% C.I. 168us-1465us Avg: 816.500us Max: 1465us
ClearFromSpace:	Sum: 1.538ms 99% C.I. 420us-1118us Avg: 769us Max: 1118us
SweepSystemWeaks:	Sum: 1.533ms 99% C.I. 623us-910us Avg: 766.500us Max: 910us
FlipOtherThreads:	Sum: 706us 99% C.I. 78us-628us Avg: 353us Max: 628us
RecordFree:	Sum: 569us 99% C.I. 265us-304us Avg: 284.500us Max: 304us
ForwardSoftReferences:	Sum: 559us 99% C.I. 5us-554us Avg: 279.500us Max: 554us
GrayAllDirtyImmuneObjects:	Sum: 437us 99% C.I. 147us-290us Avg: 218.500us Max: 290us
ClearRegionSpaceCards:	Sum: 370us 99% C.I. 93us-277us Avg: 185us Max: 277us
InitializePhase:	Sum: 355us 99% C.I. 147us-208us Avg: 177.500us Max: 208us
ProcessReferences:	Sum: 337us 99% C.I. 1us-304us Avg: 84.250us Max: 304us
VisitNonThreadRoots:	Sum: 276us 99% C.I. 67us-209us Avg: 138us Max: 209us
ThreadListFlip:	Sum: 226us 99% C.I. 63us-163us Avg: 113us Max: 163us
SweepLargeObjects:	Sum: 188us 99% C.I. 33us-155us Avg: 94us Max: 155us
(Paused)FlipCallback:	Sum: 100us 99% C.I. 44us-56us Avg: 50us Max: 56us
SweepAllocSpace:	Sum: 80us 99% C.I. 35us-45us Avg: 40us Max: 45us
ResumeRunnableThreads:	Sum: 67us 99% C.I. 19us-48us Avg: 33.500us Max: 48us
MarkStackAsLive:	Sum: 61us 99% C.I. 28us-33us Avg: 30.500us Max: 33us
(Paused)ClearCards:	Sum: 50us 99% C.I. 0.250us-9us Avg: 1.136us Max: 9us
MarkingPhase:	Sum: 48us 99% C.I. 12us-36us Avg: 24us Max: 36us
ReclaimPhase:	Sum: 41us 99% C.I. 16us-25us Avg: 20.500us Max: 25us
EmptyRBMarkBitStack:	Sum: 34us 99% C.I. 9us-25us Avg: 17us Max: 25us
SwapBitmaps:	Sum: 17us 99% C.I. 6us-11us Avg: 8.500us Max: 11us
ResumeOtherThreads:	Sum: 13us 99% C.I. 3us-10us Avg: 6.500us Max: 10us
Sweep:	Sum: 8us 99% C.I. 4us-4us Avg: 4us Max: 4us
UnBindBitmaps:	Sum: 1us 99% C.I. 250ns-1000ns Avg: 500ns Max: 1000ns
Done Dumping histograms
concurrent copying paused:	Sum: 822us 99% C.I. 304us-518us Avg: 411us Max: 518us
concurrent copying total time: 50.316ms mean time: 25.158ms
concurrent copying freed: 68961 objects with total size 10MB
concurrent copying throughput: 1.37922e+06/s / 214MB/s
Cumulative bytes moved 5614304
Cumulative objects moved 97452
Total time spent in GC: 50.316ms
Mean GC size throughput: 199MB/s
Mean GC object throughput: 1.36992e+06 objects/s
Total number of allocations 110750
Total bytes allocated 12MB
Total bytes freed 10MB
Free memory 3MB
Free memory until GC 3MB
Free memory until OOME 253MB
Total memory 6MB
Max memory 256MB
Zygote space size 896KB
Total mutator paused time: 822us
Total time waiting for GC to complete: 4.634us
Total GC count: 2
Total GC time: 50.316ms
Total blocking GC count: 0
Total blocking GC time: 0
Histogram of GC count per 10000 ms: 0:2,1:1
Histogram of blocking GC count per 10000 ms: 0:3
Registered native bytes allocated: 37955818
/data/dalvik-cache/oat/arm64/xposed_XResourcesSuperClass.odex: quicken
/data/dalvik-cache/oat/arm64/xposed_XTypedArraySuperClass.odex: quicken
/data/app/com.surcumference.fingerprintpay-JN4WUDOlFJb-i4shGHZd8w==/oat/arm64/base.odex: speed-profile
/data/app/com.jozein.xedgepro-cZAoezLvevs0vkwnROxkeA==/oat/arm64/base.odex: quicken
/data/app/com.sparetimeforu.android.sparetimeforu-pqnddOUFZ9BFqr48mFDS0A==/oat/arm64/base.odex: quicken
Current JIT code cache size: 297KB
Current JIT data cache size: 214KB
Current JIT capacity: 1024KB
Current number of JIT code cache entries: 496
Total number of JIT compilations: 542
Total number of JIT compilations for on stack replacement: 1
Total number of JIT code cache collections: 6
Memory used for stack maps: Avg: 133B Max: 19KB Min: 8B
Memory used for compiled code: Avg: 566B Max: 41KB Min: 4B
Memory used for profiling info: Avg: 160B Max: 5KB Min: 32B
Start Dumping histograms for 549 iterations for JIT timings
Compiling:	Sum: 641.981ms 99% C.I. 0.065ms-19.763ms Avg: 1.182ms Max: 58.855ms
TrimMaps:	Sum: 30.528ms 99% C.I. 7us-835.249us Avg: 56.220us Max: 1760us
Code cache collection:	Sum: 5.056ms 99% C.I. 363us-1775us Avg: 842.666us Max: 1775us
Done Dumping histograms
Memory used for compilation: Avg: 138KB Max: 8MB Min: 22KB
ProfileSaver total_bytes_written=24104
ProfileSaver total_number_of_writes=1
ProfileSaver total_number_of_code_cache_queries=1
ProfileSaver total_number_of_skipped_writes=0
ProfileSaver total_number_of_failed_writes=0
ProfileSaver total_ms_of_sleep=45000
ProfileSaver total_ms_of_work=10
ProfileSaver max_number_profile_entries_cached=2
ProfileSaver total_number_of_hot_spikes=14
ProfileSaver total_number_of_wake_ups=5

suspend all histogram:	Sum: 816us 99% C.I. 1us-267.520us Avg: 25.500us Max: 275us
DALVIK THREADS (33):
"main" prio=5 tid=1 Runnable
  | group="main" sCount=0 dsCount=0 flags=0 obj=0x741e24e0 self=0x7100ac7a00
  | sysTid=12541 nice=-10 cgrp=default sched=0/0 handle=0x71055e19b0
  | state=R schedstat=( 0 0 0 ) utm=7622 stm=20 core=5 HZ=100
  | stack=0x7fcada8000-0x7fcadaa000 stackSize=8MB
  | held mutexes= "mutator lock"(shared held)
  at com.sparetimeforu.android.sparetimeforu.fragment.STFUFragment.onFABClicked(STFUFragment.java:564)
  at com.sparetimeforu.android.sparetimeforu.fragment.STFUFragment_ViewBinding$1.doClick(STFUFragment_ViewBinding.java:29)
  at butterknife.internal.DebouncingOnClickListener.onClick(DebouncingOnClickListener.java:22)
  at android.view.View.performClick(View.java:6274)
  at android.view.View$PerformClick.run(View.java:24859)
  at android.os.Handler.handleCallback(Handler.java:789)
  at android.os.Handler.dispatchMessage(Handler.java:98)
  at android.os.Looper.loop(Looper.java:164)
  at android.app.ActivityThread.main(ActivityThread.java:6709)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:240)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:769)
  at de.robv.android.xposed.XposedBridge.main(XposedBridge.java:108)

上一篇： 操作系统