Android 系統穩定性之ANR
相信大部分Android 開發人員都遇到過ANR問題,本文根據一些實際的開發經歷介紹一下如何解決和避免ANR問題。
一,何為ANR
ANR是“Application Not Responding”的縮寫,即“應用程式無響應”。在Android中,ActivityManagerService(簡稱AMS)和WindowManagerService
(簡稱WMS)會監測應用程式的響應時間,如果應用程式主執行緒(即UI執行緒)在超時時間內對輸入事件沒有處理完畢,或者對特定操作沒有執行完畢,就會出現ANR。對於輸入事件沒有處理完畢產生的ANR,Android會顯示一個對話方塊,提示使用者當前應用程式沒有響應,使用者可以選擇繼續等待或者關閉這個應用程式(也就是殺掉這個應用程式的程序)。
產生ANR的原因:
- 主執行緒對輸入事件在5秒內沒有處理完畢
- 主執行緒在執行BroadcastReceiver的onReceive函式時10秒內沒有執行完畢
- 主執行緒在執行Service的各個生命週期函式時20秒內沒有執行完畢
由於廣播接收器和Service都是無介面的,在上述三種ANR事件中只有1有介面提示,其他兩種只輸出日誌。三種ANR均會輸出log日誌,同時還會將各個應用程式程序的函式堆疊輸出到/data/data/anr/trace.txt中,這個檔案是分析ANR原因的關鍵檔案。
二,如何分析ANR
在Android測試工具Monkey博文中介紹了通過Monkey工具可以發現一些潛在的ANR風險,這裡將介紹一旦出現ANR異常如何來分析。log和trace.txt就是兩個利器。老規矩,還是先貼個例子上來分析。
log 資訊分析:
再看trace檔案,只載錄部分::Sending Flip keyboardOpen=true :Sending Touch (ACTION_DOWN): 0:(24.0,570.0) //[calendar_time:2014-08-16 12:44:38.403 system_uptime:263794] // Sending event #3300 :Sending Touch (ACTION_UP): 0:(51.368206,570.24054) :Switch: #Intent;action=android.intent.action.MAIN;category=android.intent.category.LAUNCHER;launchFlags=0x10200000;component=com.hybroad.launcher/.activity.PreLauncherActivity;end // Allowing start of Intent { act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] cmp=com.hybroad.launcher/.activity.PreLauncherActivity } in package com.hybroad.launcher :Sending Touch (ACTION_DOWN): 0:(1101.0,1020.0) :Sending Touch (ACTION_UP): 0:(1165.5239,1050.6898) [ 183.601062] RTL871X: survey done event(2) // Rejecting start of Intent { act=android.intent.action.MAIN cat=[android.intent.category.HOME] cmp=android/com.android.internal.app.ResolverActivity } in package android :Sending Touch (ACTION_DOWN): 0:(1672.0,963.0) :Sending Touch (ACTION_UP): 0:(1607.745,971.0462) // NOT RESPONDING: com.hybroad.launcher (pid 6012) // com.hybroad.lanucher 出現了ANR,由SubMenuActivity裡的操作導致的 ANR in com.hybroad.launcher (com.hybroad.launcher/.activity.SubMenuActivity) // ANR 原因是keyDispatching 超時,UI執行緒超5秒未響應 Reason: keyDispatchingTimedOut Load: 3.97 / 2.2 / 0.93 // 下面是CPU使用率,system_server 佔用CPU過多,ago表示發生ANR之前的CPU使用情況。 //later 是ANR之後CPU使用情況 CPU usage from 6313ms to 101ms ago: 98% 1375/system_server: 52% user + 45% kernel / faults: 2239 minor 75% 1630/com.hybroad.phone_remote: 39% user + 35% kernel / faults: 131 minor 68% 2385/com.hybroad.airplay: 40% user + 28% kernel / faults: 17 minor 18% 1035/tvos: 9.3% user + 9.1% kernel 18% 6012/com.hybroad.launcher: 13% user + 5.3% kernel / faults: 3363 minor 5 major 5.6% 1019/surfaceflinger: 2% user + 3.5% kernel 2.5% 5657/mediaserver: 0.3% user + 2.2% kernel / faults: 18 minor 0.6% 1608/com.hybroad.inputmethod.remote: 0.6% user + 0% kernel / faults: 1 minor 0.6% 4772/com.android.commands.monkey: 0.3% user + 0.3% kernel / faults: 24 minor 0.3% 1029/livecap: 0% user + 0.3% kernel 0.3% 2255/RTW_CMD_THREAD: 0% user + 0.3% kernel 0.1% 5/kworker/u:0: 0% user + 0.1% kernel 0.1% 22/kworker/u:1: 0% user + 0.1% kernel 0.1% 420/cifs_mem_clear: 0.1% user + 0% kernel 0.1% 1812/mdnsd: 0% user + 0.1% kernel / faults: 1 minor 0% 2244/rel_supplicant: 0% user + 0% kernel / faults: 51 minor 3 major 49% TOTAL: 27% user + 21% kernel + 0% softirq CPU usage from 681ms to 1214ms later: 67% 1375/system_server: 37% user + 30% kernel / faults: 23 minor 7.5% 1728/Binder_7: 5.6% user + 1.8% kernel 5.6% 1688/Binder_3: 3.7% user + 1.8% kernel 5.6% 1689/Binder_4: 1.8% user + 3.7% kernel 5.6% 1729/Binder_8: 3.7% user + 1.8% kernel 5.6% 1899/Binder_A: 3.7% user + 1.8% kernel 3.7% 1375/system_server: 1.8% user + 1.8% kernel 3.7% 1386/Binder_1: 3.7% user + 0% kernel 3.7% 1387/Binder_2: 1.8% user + 1.8% kernel 3.7% 1397/ActivityManager: 0% user + 3.7% kernel 3.7% 1714/Binder_5: 1.8% user + 1.8% kernel 3.7% 1715/Binder_6: 3.7% user + 0% kernel 3.7% 1730/Binder_9: 1.8% user + 1.8% kernel 3.7% 1900/Binder_B: 3.7% user + 0% kernel 33% 1630/com.hybroad.phone_remote: 24% user + 9.4% kernel / faults: 1 minor 30% 1813/Timer-0: 22% user + 7.5% kernel 16% 1035/tvos: 3.7% user + 13% kernel 3.7% 1369/1035keypad Inpu: 1.8% user + 1.8% kernel 3.7% 1414/HDMITx_Task: 3.7% user + 0% kernel 3.7% 1700/Mdebug Monitor: 0% user + 3.7% kernel 1.8% 1406/Picture Monitor: 0% user + 1.8% kernel 1.8% 1698/Internal_MHLthr: 0% user + 1.8% kernel 3.7% 1019/surfaceflinger: 0% user + 3.7% kernel 3.7% 1186/SurfaceFlinger: 0% user + 3.7% kernel 3.7% 2385/com.hybroad.airplay: 3.7% user + 0% kernel 3.7% 2402/Timer-0: 3.7% user + 0% kernel 33% TOTAL: 17% user + 15% kernel procrank: PID Vss Rss Pss Uss cmdline 1375 70196K 69848K 47811K 44824K system_server 1515 66980K 64488K 43472K 40784K com.android.systemui 6012 55568K 43604K 23783K 21476K com.hybroad.launcher 1035 56792K 18508K 17888K 17580K /applications/bin/tvos 1630 31496K 31412K 13415K 12060K com.hybroad.phone_remote 1020 37196K 37072K 10593K 5184K zygote 5511 39404K 28252K 9760K 7964K com.android.systemui:screenshot 4772 22584K 22556K 9660K 6436K com.android.commands.monkey 1954 24868K 24780K 6770K 5188K com.miui.mihome2 1921 23480K 23388K 6647K 5312K com.miui.mihome.lockscreen 5657 10796K 10792K 6327K 5164K /system/bin/mediaserver 1532 22468K 22380K 5764K 4708K android.process.media 1660 24420K 24344K 5759K 4224K system:ui 1560 23100K 23004K 5574K 4172K com.miui.mihome2:download 1641 21048K 20948K 4481K 3524K com.jrm.servicecontainer 1608 20764K 20680K 4463K 3532K com.hybroad.inputmethod.remote 2385 18860K 18764K 3807K 3048K com.hybroad.airplay 1019 46628K 7604K 3380K 2328K /system/bin/surfaceflinger 1778 18440K 18348K 3262K 2504K com.hybroad.dlna 1574 18404K 18296K 3024K 2200K com.mstar.android.providers.tv 1794 17868K 17772K 2728K 1812K com.hybroad.phone_remote.daemon 1820 17444K 17344K 2621K 1868K org.opencv.engine:OpenCVEngineProcess 1652 17396K 17296K 2531K 1772K com.broadcom.bluetoothmonitor 1871 16808K 16712K 2434K 1708K com.android.settings 2035 16416K 16312K 2223K 1500K com.jrm.localmm 1018 2440K 2440K 2101K 2088K /system/bin/debuggerd 1905 16432K 16332K 2095K 1388K com.android.onetimeinitializer 2426 16104K 16004K 2064K 1356K com.mstar.tvsetting 1029 5072K 5072K 1818K 1260K /system/bin/livecap 1021 4372K 4372K 1490K 1024K /system/bin/drmserver 6274 1652K 1652K 1410K 1404K procrank 1028 1252K 1252K 975K 968K /system/bin/upnp_tv_receiver 2244 1892K 1892K 955K 832K rel_supplicant 1027 22020K 2180K 788K 316K /system/bin/virtualkeypad 1017 1612K 1612K 744K 644K /system/bin/netd 1015 1508K 1508K 679K 596K /system/bin/vold 1812 848K 848K 553K 544K /system/bin/mdnsd 1 536K 536K 450K 388K /init 1024 1228K 1228K 435K 360K /system/bin/keystore 2242 356K 356K 356K 356K /system/bin/busybox 1016 928K 928K 355K 316K /system/bin/resourcemanager 1031 716K 716K 226K 208K /system/bin/browserserver 2905 488K 488K 205K 128K sh 1036 476K 476K 197K 120K /system/bin/sh 2091 504K 504K 187K 176K /system/bin/dhcpcd 1023 456K 456K 162K 152K /system/bin/installd 674 220K 220K 154K 92K /sbin/ueventd 1037 168K 168K 148K 148K /sbin/adbd 6216 432K 428K 147K 132K /system/bin/dnssd 1014 348K 344K 109K 104K /system/bin/servicemanager 1026 348K 344K 105K 100K /system/bin/logwrapper 1034 332K 332K 94K 88K /system/bin/dnssd_daemon ------ ------ ------ 267207K 226160K TOTAL
----- pid 6012 at 2014-08-16 12:44:43 -----
Cmd line: com.hybroad.launcher
//開頭顯示程序號、ANR發生的時間點和程序名稱
JNI: CheckJNI is off; workarounds are off; pins=0; globals=159
DALVIK THREADS:
(mutexes: tll=0 tsl=0 tscl=0 ghl=0)
//依次是:執行緒名、執行緒優先順序、執行緒建立時的序號執行緒當前狀態
"main" prio=5 tid=1 SUSPENDED
// 執行緒名:main 優先順序5 建立序號 1 執行緒狀態:SUSPENDED
| sysTid=6012 nice=0 sched=0/0 cgrp=apps handle=1074671612
| state=S schedstat=( 2402929933 1242053208 8116 ) utm=191 stm=48 core=1
at android.view.ViewRootImpl.performTraversals(ViewRootImpl.java:~1585)
at android.view.ViewRootImpl.doTraversal(ViewRootImpl.java:1045)
at android.view.ViewRootImpl$TraversalRunnable.run(ViewRootImpl.java:5522)
at android.view.Choreographer$CallbackRecord.run(Choreographer.java:749)
at android.view.Choreographer.doCallbacks(Choreographer.java:562)
at android.view.Choreographer.doFrame(Choreographer.java:532)
at android.view.Choreographer$FrameDisplayEventReceiver.run(Choreographer.java:735)
at android.os.Handler.handleCallback(Handler.java:730)
at android.os.Handler.dispatchMessage(Handler.java:92)
at android.os.Looper.loop(Looper.java:137)
at android.app.ActivityThread.main(ActivityThread.java:5103)
at java.lang.reflect.Method.invokeNative(Native Method)
at java.lang.reflect.Method.invoke(Method.java:525)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:773)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:589)
at dalvik.system.NativeStart.main(Native Method)
"PriorityExecutor #5" prio=5 tid=15 WAIT
| group="main" sCount=1 dsCount=0 obj=0x4214d3d8 self=0x52301318
| sysTid=6041 nice=10 sched=0/0 cgrp=apps/bg_non_interactive handle=1378883432
| state=S schedstat=( 341597 4190770 3 ) utm=0 stm=0 core=0
at java.lang.Object.wait(Native Method)
- waiting on <0x4214d550> (a java.lang.VMThread) held by tid=15 (PriorityExecutor #5)
at java.lang.Thread.parkFor(Thread.java:1205)
at sun.misc.Unsafe.park(Unsafe.java:325)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:159)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2019)
at com.lidroid.xutils.task.PriorityObjectBlockingQueue.take(PriorityObjectBlockingQueue.java:274)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1013)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1073)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:573)
at java.lang.Thread.run(Thread.java:841)
"PriorityExecutor #4" prio=5 tid=14 WAIT
| group="main" sCount=1 dsCount=0 obj=0x4214c958 self=0x5272d980
| sysTid=6040 nice=10 sched=0/0 cgrp=apps/bg_non_interactive handle=1383259600
| state=S schedstat=( 16335142 37377692 95 ) utm=1 stm=0 core=0
at java.lang.Object.wait(Native Method)
- waiting on <0x4214ca98> (a java.lang.VMThread) held by tid=14 (PriorityExecutor #4)
at java.lang.Thread.parkFor(Thread.java:1205)
at sun.misc.Unsafe.park(Unsafe.java:325)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:159)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2019)
at com.lidroid.xutils.task.PriorityObjectBlockingQueue.take(PriorityObjectBlockingQueue.java:274)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1013)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1073)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:573)
at java.lang.Thread.run(Thread.java:841)
"PriorityExecutor #3" prio=5 tid=13 WAIT
| group="main" sCount=1 dsCount=0 obj=0x4214be90 self=0x5272e6a8
| sysTid=6039 nice=10 sched=0/0 cgrp=apps/bg_non_interactive handle=1383257392
| state=S schedstat=( 1407948 916560 16 ) utm=0 stm=0 core=0
at java.lang.Object.wait(Native Method)
- waiting on <0x4214c140> (a java.lang.VMThread) held by tid=13 (PriorityExecutor #3)
at java.lang.Thread.parkFor(Thread.java:1205)
at sun.misc.Unsafe.park(Unsafe.java:325)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:159)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2019)
at com.lidroid.xutils.task.PriorityObjectBlockingQueue.take(PriorityObjectBlockingQueue.java:274)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1013)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1073)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:573)
at java.lang.Thread.run(Thread.java:841)
"PriorityExecutor #2" prio=5 tid=12 WAIT
| group="main" sCount=1 dsCount=0 obj=0x42154638 self=0x5272cc90
| sysTid=6038 nice=10 sched=0/0 cgrp=apps/bg_non_interactive handle=1383256288
| state=S schedstat=( 20251581 51870492 151 ) utm=1 stm=0 core=0
at java.lang.Object.wait(Native Method)
- waiting on <0x421547d0> (a java.lang.VMThread) held by tid=12 (PriorityExecutor #2)
at java.lang.Thread.parkFor(Thread.java:1205)
at sun.misc.Unsafe.park(Unsafe.java:325)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:159)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2019)
at com.lidroid.xutils.task.PriorityObjectBlockingQueue.take(PriorityObjectBlockingQueue.java:274)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1013)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1073)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:573)
at java.lang.Thread.run(Thread.java:841)
"PriorityExecutor #1" prio=5 tid=11 WAIT
| group="main" sCount=1 dsCount=0 obj=0x42154370 self=0x52730630
| sysTid=6037 nice=10 sched=0/0 cgrp=apps/bg_non_interactive handle=1103892024
| state=S schedstat=( 2237642 16217040 18 ) utm=0 stm=0 core=0
at java.lang.Object.wait(Native Method)
- waiting on <0x42154530> (a java.lang.VMThread) held by tid=11 (PriorityExecutor #1)
at java.lang.Thread.parkFor(Thread.java:1205)
at sun.misc.Unsafe.park(Unsafe.java:325)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:159)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2019)
at com.lidroid.xutils.task.PriorityObjectBlockingQueue.take(PriorityObjectBlockingQueue.java:274)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1013)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1073)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:573)
at java.lang.Thread.run(Thread.java:841)
"Binder_2" prio=5 tid=10 NATIVE
| group="main" sCount=1 dsCount=0 obj=0x421416c0 self=0x41c1e638
| sysTid=6024 nice=0 sched=0/0 cgrp=apps handle=1103225840
| state=S schedstat=( 2307968 2046145 22 ) utm=0 stm=0 core=0
#00 pc 0001b320 /system/lib/libc.so (__ioctl+8)
#01 pc 0002b9ab /system/lib/libc.so (ioctl+14)
#02 pc 0001b539 /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+140)
#03 pc 0001bcd7 /system/lib/libbinder.so (android::IPCThreadState::joinThreadPool(bool)+154)
#04 pc 0001fae9 /system/lib/libbinder.so
#05 pc 00011a8d /system/lib/libutils.so (android::Thread::_threadLoop(void*)+216)
#06 pc 0004bd21 /system/lib/libandroid_runtime.so (android::AndroidRuntime::javaThreadShell(void*)+68)
#07 pc 00011581 /system/lib/libutils.so
#08 pc 0000ca58 /system/lib/libc.so (__thread_entry+72)
#09 pc 0000cbd4 /system/lib/libc.so (pthread_create+208)
at dalvik.system.NativeStart.run(Native Method)
"Binder_1" prio=5 tid=9 NATIVE
| group="main" sCount=1 dsCount=0 obj=0x421409b8 self=0x41c1db88
| sysTid=6023 nice=0 sched=0/0 cgrp=apps handle=1103223104
| state=S schedstat=( 3963651 6845165 24 ) utm=0 stm=0 core=2
#00 pc 0001b320 /system/lib/libc.so (__ioctl+8)
#01 pc 0002b9ab /system/lib/libc.so (ioctl+14)
#02 pc 0001b539 /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+140)
#03 pc 0001bcd7 /system/lib/libbinder.so (android::IPCThreadState::joinThreadPool(bool)+154)
#04 pc 0001fae9 /system/lib/libbinder.so
#05 pc 00011a8d /system/lib/libutils.so (android::Thread::_threadLoop(void*)+216)
#06 pc 0004bd21 /system/lib/libandroid_runtime.so (android::AndroidRuntime::javaThreadShell(void*)+68)
#07 pc 00011581 /system/lib/libutils.so
#08 pc 0000ca58 /system/lib/libc.so (__thread_entry+72)
#09 pc 0000cbd4 /system/lib/libc.so (pthread_create+208)
at dalvik.system.NativeStart.run(Native Method)
"FinalizerWatchdogDaemon" daemon prio=5 tid=8 WAIT
| group="system" sCount=1 dsCount=0 obj=0x4213d7e8 self=0x41c1d0a0
| sysTid=6022 nice=0 sched=0/0 cgrp=apps handle=1103222000
| state=S schedstat=( 169252 273121 4 ) utm=0 stm=0 core=2
at java.lang.Object.wait(Native Method)
- waiting on <0x41ea2830> (a java.lang.Daemons$FinalizerWatchdogDaemon)
at java.lang.Object.wait(Object.java:364)
at java.lang.Daemons$FinalizerWatchdogDaemon.waitForObject(Daemons.java:230)
at java.lang.Daemons$FinalizerWatchdogDaemon.run(Daemons.java:207)
at java.lang.Thread.run(Thread.java:841)
"FinalizerDaemon" daemon prio=5 tid=7 WAIT
| group="system" sCount=1 dsCount=0 obj=0x4213d638 self=0x59cd1148
| sysTid=6021 nice=0 sched=0/0 cgrp=apps handle=1506612632
| state=S schedstat=( 19178147 5530289 45 ) utm=1 stm=0 core=3
at java.lang.Object.wait(Native Method)
- waiting on <0x41e8b568> (a java.lang.ref.ReferenceQueue)
at java.lang.Object.wait(Object.java:401)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:102)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:73)
at java.lang.Daemons$FinalizerDaemon.run(Daemons.java:170)
at java.lang.Thread.run(Thread.java:841)
"ReferenceQueueDaemon" daemon prio=5 tid=6 WAIT
| group="system" sCount=1 dsCount=0 obj=0x4213d4d0 self=0x59cd08a8
| sysTid=6020 nice=0 sched=0/0 cgrp=apps handle=1506610424
| state=S schedstat=( 2228290 3801987 33 ) utm=0 stm=0 core=2
at java.lang.Object.wait(Native Method)
- waiting on <0x41e8b490>
at java.lang.Object.wait(Object.java:364)
at java.lang.Daemons$ReferenceQueueDaemon.run(Daemons.java:130)
at java.lang.Thread.run(Thread.java:841)
"Compiler" daemon prio=5 tid=5 VMWAIT
| group="system" sCount=1 dsCount=0 obj=0x4213d3e0 self=0x59cd0250
| sysTid=6019 nice=0 sched=0/0 cgrp=apps handle=1506607112
| state=S schedstat=( 365619316 81085896 3099 ) utm=17 stm=18 core=1
#00 pc 0001c5f0 /system/lib/libc.so (__futex_syscall3+8)
#01 pc 0000e6a8 /system/lib/libc.so (__pthread_cond_timedwait_relative+48)
#02 pc 0000e708 /system/lib/libc.so (__pthread_cond_timedwait+64)
#03 pc 0007307b /system/lib/libdvm.so
#04 pc 0005440d /system/lib/libdvm.so
#05 pc 0000ca58 /system/lib/libc.so (__thread_entry+72)
#06 pc 0000cbd4 /system/lib/libc.so (pthread_create+208)
at dalvik.system.NativeStart.run(Native Method)
"JDWP" daemon prio=5 tid=4 VMWAIT
| group="system" sCount=1 dsCount=0 obj=0x4213d2f8 self=0x59298370
| sysTid=6018 nice=0 sched=0/0 cgrp=apps handle=1495892264
| state=S schedstat=( 526723 2311140 11 ) utm=0 stm=0 core=2
#00 pc 0001c0c4 /system/lib/libc.so (recvmsg+8)
#01 pc 00060a5b /system/lib/libdvm.so
#02 pc 00060c8f /system/lib/libdvm.so
#03 pc 0006395f /system/lib/libdvm.so
#04 pc 0005440d /system/lib/libdvm.so
#05 pc 0000ca58 /system/lib/libc.so (__thread_entry+72)
#06 pc 0000cbd4 /system/lib/libc.so (pthread_create+208)
at dalvik.system.NativeStart.run(Native Method)
"Signal Catcher" daemon prio=5 tid=3 RUNNABLE
| group="system" sCount=0 dsCount=0 obj=0x4213d200 self=0x59297ad0
| sysTid=6017 nice=0 sched=0/0 cgrp=apps handle=1495890056
| state=R schedstat=( 17944062 3806465 24 ) utm=1 stm=0 core=2
at dalvik.system.NativeStart.run(Native Method)
"GC" daemon prio=5 tid=2 VMWAIT
| group="system" sCount=1 dsCount=0 obj=0x4213d120 self=0x59297230
| sysTid=6016 nice=0 sched=0/0 cgrp=apps handle=1495887848
| state=S schedstat=( 46052188 14643875 115 ) utm=3 stm=0 core=0
#00 pc 0001c5f0 /system/lib/libc.so (__futex_syscall3+8)
#01 pc 0000e6a8 /system/lib/libc.so (__pthread_cond_timedwait_relative+48)
#02 pc 0000e708 /system/lib/libc.so (__pthread_cond_timedwait+64)
#03 pc 00071d5f /system/lib/libdvm.so
#04 pc 0005440d /system/lib/libdvm.so
#05 pc 0000ca58 /system/lib/libc.so (__thread_entry+72)
#06 pc 0000cbd4 /system/lib/libc.so (pthread_create+208)
at dalvik.system.NativeStart.run(Native Method)
NATIVE THREADS:
"ybroad.launcher" sysTid=6044 nice=0 sched=0/0 cgrp=apps
| state=S schedstat=( 28535 0 1 ) utm=0 stm=0 core=2
"ybroad.launcher" sysTid=6045 nice=0 sched=0/0 cgrp=apps
| state=S schedstat=( 5934826 18041494 192 ) utm=0 stm=0 core=0
"ybroad.launcher" sysTid=6047 nice=0 sched=0/0 cgrp=apps
| state=S schedstat=( 41991903 31647623 449 ) utm=0 stm=3 core=0
"ybroad.launcher" sysTid=6048 nice=0 sched=0/0 cgrp=apps
| state=S schedstat=( 8821631 43405553 239 ) utm=0 stm=0 core=1
----- end 6012 -----
----- pid 1375 at 2014-08-16 12:44:43 -----
Cmd line: system_server
JNI: CheckJNI is off; workarounds are off; pins=3; globals=593 (plus 30 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=0x41e9a578 self=0x41d10778
| sysTid=1375 nice=0 sched=0/0 cgrp=apps handle=1074671612
| state=S schedstat=( 23099158711 5734754939 194687 ) utm=1476 stm=833 core=0
#00 pc 0001b320 /system/lib/libc.so (__ioctl+8)
#01 pc 0002b9ab /system/lib/libc.so (ioctl+14)
#02 pc 0001b539 /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+140)
#03 pc 0001bcd7 /system/lib/libbinder.so (android::IPCThreadState::joinThreadPool(bool)+154)
#04 pc 000013c3 /system/lib/libsystem_server.so (system_init+378)
#05 pc 0001dc4c /system/lib/libdvm.so (dvmPlatformInvoke+112)
#06 pc 0004df2f /system/lib/libdvm.so (dvmCallJNIMethod(unsigned int const*, JValue*, Method const*, Thread*)+398)
#07 pc 00027060 /system/lib/libdvm.so
#08 pc 0002b64c /system/lib/libdvm.so (dvmInterpret(Thread*, Method const*, JValue*)+184)
#09 pc 0006023f /system/lib/libdvm.so (dvmInvokeMethod(Object*, Method const*, ArrayObject*, ArrayObject*, ClassObject*, bool)+350)
#10 pc 00067e3f /system/lib/libdvm.so
#11 pc 00027060 /system/lib/libdvm.so
#12 pc 0002b64c /system/lib/libdvm.so (dvmInterpret(Thread*, Method const*, JValue*)+184)
#13 pc 0005ff81 /system/lib/libdvm.so (dvmCallMethodV(Thread*, Method const*, Object*, bool, JValue*, std::__va_list)+292)
#14 pc 00049bc7 /system/lib/libdvm.so
#15 pc 0004bd87 /system/lib/libandroid_runtime.so
#16 pc 0004ca17 /system/lib/libandroid_runtime.so (android::AndroidRuntime::start(char const*, char const*)+378)
#17 pc 0000105b /system/bin/app_process
#18 pc 0000db4f /system/lib/libc.so (__libc_init+50)
#19 pc 00000d7c /system/bin/app_process
at com.android.server.SystemServer.init1(Native Method)
at com.android.server.SystemServer.main(SystemServer.java:1183)
at java.lang.reflect.Method.invokeNative(Native Method)
at java.lang.reflect.Method.invoke(Method.java:525)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:773)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:589)
at dalvik.system.NativeStart.main(Native Method)
"AsyncTask #2" prio=5 tid=89 WAIT
| group="main" sCount=1 dsCount=0 obj=0x423a6b98 self=0x59771d08
| sysTid=2391 nice=0 sched=0/0 cgrp=apps handle=1500973936
| state=S schedstat=( 3672799 2067535 16 ) utm=0 stm=0 core=3
at java.lang.Object.wait(Native Method)
- waiting on <0x421a1be8> (a java.lang.VMThread) held by tid=89 (AsyncTask #2)
at java.lang.Thread.parkFor(Thread.java:1205)
at sun.misc.Unsafe.park(Unsafe.java:325)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:159)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2019)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:413)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1013)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1073)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:573)
at java.lang.Thread.run(Thread.java:841)
"WifiMonitor" prio=5 tid=88 NATIVE
| group="main" sCount=1 dsCount=0 obj=0x42334b20 self=0x59767270
| sysTid=2262 nice=0 sched=0/0 cgrp=apps handle=1496667712
| state=S schedstat=( 2650153 18957633 18 ) utm=0 stm=0 core=2
#00 pc 0001c4b0 /system/lib/libc.so (poll+12)
#01 pc 00005ccb /system/lib/libhardware_legacy.so (wifi_ctrl_recv+66)
#02 pc 00005d85 /system/lib/libhardware_legacy.so (wifi_wait_on_socket+44)
#03 pc 0006bd8f /system/lib/libandroid_runtime.so
#04 pc 0001dc4c /system/lib/libdvm.so (dvmPlatformInvoke+112)
#05 pc 0004df2f /system/lib/libdvm.so (dvmCallJNIMethod(unsigned int const*, JValue*, Method const*, Thread*)+398)
#06 pc 00027060 /system/lib/libdvm.so
#07 pc 0002b64c /system/lib/libdvm.so (dvmInterpret(Thread*, Method const*, JValue*)+184)
#08 pc 0005ff81 /system/lib/libdvm.so (dvmCallMethodV(Thread*, Method const*, Object*, bool, JValue*, std::__va_list)+292)
#09 pc 0005ffab /system/lib/libdvm.so (dvmCallMethod(Thread*, Method const*, Object*, JValue*, ...)+20)
#10 pc 00054d2b /system/lib/libdvm.so
#11 pc 0000ca58 /system/lib/libc.so (__thread_entry+72)
#12 pc 0000cbd4 /system/lib/libc.so (pthread_create+208)
at android.net.wifi.WifiNative.waitForEvent(Native Method)
at android.net.wifi.WifiNative.waitForEvent(WifiNative.java:101)
at android.net.wifi.WifiMonitor$MonitorThread.run(WifiMonitor.java:428)
"WifiMonitor" prio=5 tid=79 NATIVE
| group="main" sCount=1 dsCount=0 obj=0x423b1ab8 self=0x59766e20
| sysTid=2243 nice=0 sched=0/0 cgrp=apps handle=1500579736
| state=S schedstat=( 18832173 27053387 77 ) utm=0 stm=1 core=1
#00 pc 0001c4b0 /system/lib/libc.so (poll+12)
#01 pc 00005ccb /system/lib/libhardware_legacy.so (wifi_ctrl_recv+66)
#02 pc 00005d85 /system/lib/libhardware_legacy.so (wifi_wait_on_socket+44)
#03 pc 0006bd8f /system/lib/libandroid_runtime.so
#04 pc 0001dc4c /system/lib/libdvm.so (dvmPlatformInvoke+112)
#05 pc 0004df2f /system/lib/libdvm.so (dvmCallJNIMethod(unsigned int const*, JValue*, Method const*, Thread*)+398)
#06 pc 00027060 /system/lib/libdvm.so
#07 pc 0002b64c /system/lib/libdvm.so (dvmInterpret(Thread*, Method const*, JValue*)+184)
#08 pc 0005ff81 /system/lib/libdvm.so (dvmCallMethodV(Thread*, Method const*, Object*, bool, JValue*, std::__va_list)+292)
#09 pc 0005ffab /system/lib/libdvm.so (dvmCallMethod(Thread*, Method const*, Object*, JValue*, ...)+20)
#10 pc 00054d2b /system/lib/libdvm.so
#11 pc 0000ca58 /system/lib/libc.so (__thread_entry+72)
#12 pc 0000cbd4 /system/lib/libc.so (pthread_create+208)
at android.net.wifi.WifiNative.waitForEvent(Native Method)
at android.net.wifi.WifiNative.waitForEvent(WifiNative.java:101)
at android.net.wifi.WifiMonitor$MonitorThread.run(WifiMonitor.java:428)
"Binder_C" prio=5 tid=87 NATIVE
| group="main" sCount=1 dsCount=0 obj=0x423125c0 self=0x5977ef58
| sysTid=1901 nice=0 sched=0/0 cgrp=apps handle=1496648368
| state=S schedstat=( 26136515152 5573609667 186413 ) utm=1517 stm=1096 core=3
#00 pc 0001c5f4 /system/lib/libc.so (__futex_syscall3+12)
#01 pc 0000e6a8 /system/lib/libc.so (__pthread_cond_timedwait_relative+48)
#02 pc 00020771 /system/lib/libinput.so
#03 pc 00022019 /system/lib/libinput.so (android::InputDispatcher::injectInputEvent(android::InputEvent const*, int, int, int, int, unsigned int)+800)
#04 pc 0000a9ff /system/lib/libandroid_servers.so
#05 pc 0001dc4c /system/lib/libdvm.so (dvmPlatformInvoke+112)
#06 pc 0004df2f /system/lib/libdvm.so (dvmCallJNIMethod(unsigned int const*, JValue*, Method const*, Thread*)+398)
#07 pc 00027060 /system/lib/libdvm.so
#08 pc 0002b64c /system/lib/libdvm.so (dvmInterpret(Thread*, Method const*, JValue*)+184)
#09 pc 0005ff81 /system/lib/libdvm.so (dvmCallMethodV(Thread*, Method const*, Object*, bool, JValue*, std::__va_list)+292)
#10 pc 0004cc91 /system/lib/libdvm.so
#11 pc 0006b213 /system/lib/libandroid_runtime.so
#12 pc 0006f82f /system/lib/libandroid_runtime.so
#13 pc 00017f1d /system/lib/libbinder.so (android::BBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+60)
#14 pc 0001b8e5 /system/lib/libbinder.so (android::IPCThreadState::executeCommand(int)+508)
#15 pc 0001bcf3 /system/lib/libbinder.so (android::IPCThreadState::joinThreadPool(bool)+182)
#16 pc 0001fae9 /system/lib/libbinder.so
#17 pc 00011a8d /system/lib/libutils.so (android::Thread::_threadLoop(void*)+216)
#18 pc 0004bd21 /system/lib/libandroid_runtime.so (android::AndroidRuntime::javaThreadShell(void*)+68)
#19 pc 00011581 /system/lib/libutils.so
#20 pc 0000ca58 /system/lib/libc.so (__thread_entry+72)
#21 pc 0000cbd4 /system/lib/libc.so (pthread_create+208)
at com.android.server.input.InputManagerService.nativeInjectInputEvent(Native Method)
at com.android.server.input.InputManagerService.injectInputEvent(InputManagerService.java:534)
at android.hardware.input.IInputManager$Stub.onTransact(IInputManager.java:170)
at android.os.Binder.execTransact(Binder.java:388)
at dalvik.system.NativeStart.run(Native Method)
"Binder_B" prio=5 tid=86 NATIVE
| group="main" sCount=1 dsCount=0 obj=0x4236ee80 self=0x5978c908
| sysTid=1900 nice=0 sched=0/0 cgrp=apps handle=1501033856
| state=S schedstat=( 18675932575 2816663578 195259 ) utm=1086 stm=781 core=0
#00 pc 0001b320 /system/lib/libc.so (__ioctl+8)
#01 pc 0002b9ab /system/lib/libc.so (ioctl+14)
#02 pc 0001b539 /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+140)
#03 pc 0001bcd7 /system/lib/libbinder.so (android::IPCThreadState::joinThreadPool(bool)+154)
#04 pc 0001fae9 /system/lib/libbinder.so
#05 pc 00011a8d /system/lib/libutils.so (android::Thread::_threadLoop(void*)+216)
#06 pc 0004bd21 /system/lib/libandroid_runtime.so (android::AndroidRuntime::javaThreadShell(void*)+68)
#07 pc 00011581 /system/lib/libutils.so
#08 pc 0000ca58 /system/lib/libc.so (__thread_entry+72)
#09 pc 0000cbd4 /system/lib/libc.so (pthread_create+208)
at dalvik.system.NativeStart.run(Native Method)
"Binder_A" prio=5 tid=82 NATIVE
| group="main" sCount=1 dsCount=0 obj=0x422c66e0 self=0x59288458
| sysTid=1899 nice=0 sched=0/0 cgrp=apps handle=1473754056
| state=S schedstat=( 28407006674 1139065291 197317 ) utm=1753 stm=1086 core=3
#00 pc 0001b320 /system/lib/libc.so (__ioctl+8)
#01 pc 0002b9ab /system/lib/libc.so (ioctl+14)
#02 pc 0001b539 /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+140)
#03 pc 0001bcd7 /system/lib/libbinder.so (android::IPCThreadState::joinThreadPool(bool)+154)
#04 pc 0001fae9 /system/lib/libbinder.so
#05 pc 00011a8d /system/lib/libutils.so (android::Thread::_threadLoop(void*)+216)
#06 pc 0004bd21 /system/lib/libandroid_runtime.so (android::AndroidRuntime::javaThreadShell(void*)+68)
#07 pc 00011581 /system/lib/libutils.so
#08 pc 0000ca58 /system/lib/libc.so (__thread_entry+72)
#09 pc 0000cbd4 /system/lib/libc.so (pthread_create+208)
at dalvik.system.NativeStart.run(Native Method)
"pool-1-thread-1" prio=5 tid=85 WAIT
| group="main" sCount=1 dsCount=0 obj=0x42360de0 self=0x5977c7c8
| sysTid=1869 nice=0 sched=0/0 cgrp=apps handle=1501023256
| state=S schedstat=( 36792546 37524468 105 ) utm=2 stm=1 core=1
at java.lang.Object.wait(Native Method)
- waiting on <0x422ad870> (a java.lang.VMThread) held by tid=85 (pool-1-thread-1)
at java.lang.Thread.parkFor(Thread.java:1205)
at sun.misc.Unsafe.park(Unsafe.java:325)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:159)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2019)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:413)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1013)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1073)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:573)
at java.lang.Thread.run(Thread.java:841)
"SoundPoolThread" prio=5 tid=84 NATIVE
| group="main" sCount=1 dsCount=0 obj=0x4234dd18 self=0x59288008
| sysTid=1787 nice=0 sched=0/0 cgrp=apps handle=1501052992
| state=S schedstat=( 2719918 1463037 21 ) utm=0 stm=0 core=1
#00 pc 0001c5f0 /system/lib/libc.so (__futex_syscall3+8)
#01 pc 0000e6a8 /system/lib/libc.so (__pthread_cond_timedwait_relative+48)
#02 pc 0000e708 /system/lib/libc.so (__pthread_cond_timedwait+64)
#03 pc 000697e9 /system/lib/libmedia.so
#04 pc 0006983b /system/lib/libmedia.so (android::SoundPoolThread::read()+16)
#05 pc 000699e7 /system/lib/libmedia.so (android::SoundPoolThread::run()+14)
#06 pc 0004bd21 /system/lib/libandroid_runtime.so (android::AndroidRuntime::javaThreadShell(void*)+68)
#07 pc 00011581 /system/lib/libutils.so
#08 pc 0000ca58 /system/lib/libc.so (__thread_entry+72)
#09 pc 0000cbd4 /system/lib/libc.so (pthread_create+208)
at dalvik.system.NativeStart.run(Native Method)
"SoundPool" prio=5 tid=83 NATIVE
| group="main" sCount=1 dsCount=0 obj=0x422b7470 self=0x5977fdc8
| sysTid=1785 nice=0 sched=0/0 cgrp=apps handle=1501039224
| state=S schedstat=( 43918396 52908113 631 ) utm=0 stm=4 core=1
#00 pc 0001c5f0 /system/lib/libc.so (__futex_syscall3+8)
#01 pc 0000e6a8 /system/lib/libc.so (__pthread_cond_timedwait_relative+48)
#02 pc 0000e708 /system/lib/libc.so (__pthread_cond_timedwait+64)
#03 pc 0006937f /system/lib/libmedia.so (android::SoundPool::run()+20)
#04 pc 0004bd21 /system/lib/libandroid_runtime.so (android::AndroidRuntime::javaThreadShell(void*)+68)
#05 pc 00011581 /system/lib/libutils.so
#06 pc 0000ca58 /system/lib/libc.so (__thread_entry+72)
#07 pc 0000cbd4 /system/lib/libc.so (pthread_create+208)
at dalvik.system.NativeStart.run(Native Method)
參考frameworks\base\services\java\com\android\server\am\ActivityManagerService.java 中的appNotResponding函式的處理流程可以看出trace.txt 檔案的生成過程,在trace.txt
檔案中一般第一程序為發生ANR的程序。分析上面的trace.txt中的第一個程序 com.hybroad.launcher是產生ANR的程序,與Log日誌也匹配,通過檢視執行緒狀態,可以看出ViewRoot重新整理UI是阻塞了。trace日誌中還能看出com.hybroad.launcher中多個非同步任務都是在在WAIT狀態,如PriorityExecutor
#5" prio=5 tid=15 WAIT,這些非同步任務是從後臺下載圖片顯示。這裡巧合的是Monkey程式觸發的操作邏輯導致UI重新整理阻塞。
三、如何避免ANR
要想不出現ANR是很困難的,但也是有辦法能避免的。在主執行緒中所做的任何耗時的操作都有可能造成ANR,因為這些耗時的操作會使得主執行緒沒有機會處理使用者輸入事件或者廣播事件。因此在主執行緒中執行的任何函式所做的工作都應該儘可能的少,特別是對於Activity的生命週期函式來說。網路和資料庫操作,讀寫裝置,以及諸如點陣圖變換的一些耗時的操作,都應該放在子執行緒中完成。主執行緒不需要等待子執行緒的執行,主執行緒應該建立一個與其繫結的Handler物件,子執行緒執行完畢後通過
Handler通知主執行緒。