想必做過Android開發(fā)的童鞋都遇到過anr(Application Not Responding)代咸。一般的做法就是去/data/anr/trace.txt取對應的 文件。然后,再從這一堆龐大的堆棧信息找到自己想要的結果潦刃。但是拿到一堆arn堆棧信息很抓狂变隔,如何從這龐大的堆棧信息找到自己的問題代碼呢?這篇文章茵宪,給大家分享下如何取定位anr問題最冰。
首先看下堆棧信息
07-26 17:51:04.442: E/ActivityManager(2258): ANR in com.pafinancialtech.zijinbank (com.pafinancialtech.zijinbank/com.pingan.fstandard.paff.activity.MainActivity)
07-26 17:51:04.442: E/ActivityManager(2258): PID: 28560
07-26 17:51:04.442: E/ActivityManager(2258): Reason: Input dispatching timed out (Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago. Wait queue length: 11. Wait queue head age: 5573.8ms.)
07-26 17:51:04.442: E/ActivityManager(2258): Load: 5.15 / 3.68 / 3.38
07-26 17:51:04.442: E/ActivityManager(2258): CPU usage from 602ms to -6091ms ago:
07-26 17:51:04.442: E/ActivityManager(2258): 65% 2258/system_server: 14% user + 50% kernel / faults: 9262 minor
07-26 17:51:04.442: E/ActivityManager(2258): 47% 28560/com.pafinancialtech.zijinbank: 10% user + 37% kernel / faults: 4197 minor
07-26 17:51:04.442: E/ActivityManager(2258): 11% 4292/com.android.systemui: 5.9% user + 5.6% kernel / faults: 2762 minor
07-26 17:51:04.442: E/ActivityManager(2258): 9.2% 4819/com.android.phone: 3.1% user + 6.1% kernel / faults: 3972 minor
07-26 17:51:04.442: E/ActivityManager(2258): 1.9% 4774/com.vivo.daemonService: 0.6% user + 1.3% kernel / faults: 3167 minor
07-26 17:51:04.442: E/ActivityManager(2258): 3.5% 4618/com.baidu.map.location: 1.7% user + 1.7% kernel / faults: 3635 minor
07-26 17:51:04.442: E/ActivityManager(2258): 3.5% 28690/com.pafinancialtech.zijinbank:remote: 2.3% user + 1.1% kernel / faults: 2368 minor
07-26 17:51:04.442: E/ActivityManager(2258): 0% 4580/debuggerd64: 0% user + 0% kernel / faults: 2492 minor
07-26 17:51:04.442: E/ActivityManager(2258): 0.4% 4842/com.vivo.abe: 0.3% user + 0.1% kernel / faults: 1455 minor
07-26 17:51:04.442: E/ActivityManager(2258): 0% 4705/com.android.server.telecom: 0% user + 0% kernel / faults: 1677 minor
07-26 17:51:04.442: E/ActivityManager(2258): 0% 4867/com.vivo.fingerprint.fpc.service: 0% user + 0% kernel / faults: 1456 minor
07-26 17:51:04.442: E/ActivityManager(2258): 0% 4735/com.qualcomm.qti.services.secureui:sui_service: 0% user + 0% kernel / faults: 1503 minor
07-26 17:51:04.442: E/ActivityManager(2258): 1.3% 4165/adbd: 0.1% user + 1.1% kernel / faults: 72 minor
07-26 17:51:04.442: E/ActivityManager(2258): 0% 28661/debuggerd: 0% user + 0% kernel / faults: 820 minor
07-26 17:51:04.442: E/ActivityManager(2258): 0.5% 24757/logcat: 0.1% user + 0.4% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 0.5% 28524/kworker/u16:3: 0% user + 0.5% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 0.5% 28909/kworker/u16:4: 0% user + 0.5% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 0.4% 181/cfinteractive: 0% user + 0.4% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 0.4% 26204/logcat: 0.4% user + 0% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 0.1% 4215/VosMCThread: 0% user + 0.1% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 0.1% 4217/VosRXThread: 0% user + 0.1% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 0.1% 5999/core_ctl/0: 0% user + 0.1% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 0.2% 28467/irq/13-synaptic: 0% user + 0.2% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 0% 3/ksoftirqd/0: 0% user + 0% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 0.1% 6/kworker/u16:0: 0% user + 0.1% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 0% 7/migration/0: 0% user + 0% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 0% 8/rcu_preempt: 0% user + 0% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 0% 19/migration/3: 0% user + 0% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 0% 20/ksoftirqd/3: 0% user + 0% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 0.1% 35/kworker/u17:0: 0% user + 0.1% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 0% 207/mmcqd/0: 0% user + 0% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 0.1% 296/surfaceflinger: 0.1% user + 0% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 0% 611/kworker/3:2: 0% user + 0% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 0% 4216/VosTXThread: 0% user + 0% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 0% 5985/migration/5: 0% user + 0% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 0% 6033/perfd: 0% user + 0% kernel / faults: 4 minor
07-26 17:51:04.442: E/ActivityManager(2258): 0% 27164/kworker/6:0: 0% user + 0% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 0.-4% TOTAL: 0% user + 0.-1% kernel + 0.-3% iowait
07-26 17:51:04.442: E/ActivityManager(2258): CPU usage from 5196ms to 5716ms later:
07-26 17:51:04.442: E/ActivityManager(2258): 23% 4292/com.android.systemui: 13% user + 9.6% kernel / faults: 305 minor
07-26 17:51:04.442: E/ActivityManager(2258): 23% 4308/Signal Catcher: 13% user + 9.6% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 5.7% 2258/system_server: 1.9% user + 3.8% kernel / faults: 6 minor
07-26 17:51:04.442: E/ActivityManager(2258): 1.9% 2346/ActivityManager: 1.9% user + 0% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 1.9% 3244/SensorService: 0% user + 1.9% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 1.4% 35/kworker/u17:0: 0% user + 1.4% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 1.6% 4215/VosMCThread: 0% user + 1.6% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 1.9% 4618/com.baidu.map.location: 1.9% user + 0% kernel / faults: 823 minor
07-26 17:51:04.442: E/ActivityManager(2258): 1.9% 4647/GCDaemon: 1.9% user + 0% kernel
07-26 17:51:04.442: E/ActivityManager(2258): +0% 28983/Thread-37982: 0% user + 0% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 1.7% 28524/kworker/u16:3: 0% user + 1.7% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 1.7% 28560/com.pafinancialtech.zijinbank: 1.7% user + 0% kernel / faults: 7 minor
07-26 17:51:04.442: E/ActivityManager(2258): 1.8% 28690/com.pafinancialtech.zijinbank:remote: 1.8% user + 0% kernel / faults: 274 minor
07-26 17:51:04.442: E/ActivityManager(2258): 1.8% 28723/ServiceStartArg: 1.8% user + 0% kernel
07-26 17:51:04.442: E/ActivityManager(2258): 0.1% TOTAL: 0% user + 0% kernel + 0.1% iowait
從上面的堆棧信息,我們搜索關鍵字anr稀火,可以找到
07-26 17:51:04.442: E/ActivityManager(2258): ANR in com.pafinancialtech.zijinbank (com.pafinancialtech.zijinbank/com.pingan.fstandard.paff.activity.MainActivity)
解讀:在07-26 17點51分04秒442毫秒的時候 ActivityManager (進程號為2258) 發(fā)生了如下錯誤:com.pafinancialtech.zijinbank 包下面的MainActivity 無響應
第三行
Reason: Input dispatching timed out (Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago. Wait queue length: 11. Wait queue head age: 5573.8ms.)
解讀:keyDispatchingTimeOut - 按鍵分配超時
第四行
07-26 17:51:04.442: E/ActivityManager(2258): Load: 5.15 / 3.68 / 3.38
解讀:5分鐘暖哨,10分鐘,15分鐘內的平均負載分別為:5.15 , 3.68 , 3.38
第五行
07-26 17:51:04.442: E/ActivityManager(2258): CPU usage from 602ms to -6091ms ago:
解讀:cpu從602毫秒到6091毫秒之間的使用情況凰狞,也就是后面輸出的一堆log信息篇裁。
至此,我們可以了解大概的原因了赡若,程序肯定有地方做了耗時操作达布,但是具體在哪部分代碼出現(xiàn)的問題呢,繼續(xù)從堆棧信息查找逾冬,然并未找到突破口黍聂。既然堆棧信息沒有可用信息了,我們再分析虛擬機信息 身腻,找到從手機pull出來的anr文件产还, 搜索“Dalvik Thread”關鍵詞,快速定位到本應用程序的虛擬機信息日志嘀趟,如下:
DALVIK THREADS (91):
"main" prio=5 tid=1 Native
| group="main" sCount=1 dsCount=0 obj=0x745bd000 self=0xab1951a8
| sysTid=24311 nice=-6 cgrp=apps sched=0/0 handle=0xf716dec8
| state=S schedstat=( 4172755721 1784708550 9755 ) utm=340 stm=77 core=0 HZ=100
| stack=0xff6cf000-0xff6d1000 stackSize=8MB
| held mutexes=
kernel: __switch_to+0x70/0x7c
kernel: binder_thread_read+0x464/0xe8c
kernel: binder_ioctl+0x3f8/0x824
kernel: compat_sys_ioctl+0x10c/0x11fc
kernel: cpu_switch_to+0x48/0x4c
native: #00 pc 00039cc4 /system/lib/libc.so (__ioctl+8)
native: #01 pc 0003f4bd /system/lib/libc.so (ioctl+14)
native: #02 pc 0001ccd3 /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+190)
native: #03 pc 0001d347 /system/lib/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+42)
native: #04 pc 0001d509 /system/lib/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+124)
native: #05 pc 0001872b /system/lib/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+30)
native: #06 pc 00082b53 /system/lib/libandroid_runtime.so (???)
native: #07 pc 00a80891 /system/framework/arm/boot.oat (Java_android_os_BinderProxy_transactNative__ILandroid_os_Parcel_2Landroid_os_Parcel_2I+144)
at android.os.BinderProxy.transactNative(Native method)
at android.os.BinderProxy.transact(Binder.java:496)
at android.location.ILocationManager$Stub$Proxy.getFromLocation(ILocationManager.java:777)
at android.location.Geocoder.getFromLocation(Geocoder.java:133)
at bonree.com.bonree.agent.android.harvest.f.a(unavailable:-1)
at bonree.com.bonree.agent.android.harvest.j.onLocationChanged(unavailable:-1)
at android.location.LocationManager$ListenerTransport._handleMessage(LocationManager.java:281)
at android.location.LocationManager$ListenerTransport.access$000(LocationManager.java:210)
at android.location.LocationManager$ListenerTransport$1.handleMessage(LocationManager.java:226)
at android.os.Handler.dispatchMessage(Handler.java:102)
at android.os.Looper.loop(Looper.java:135)
at android.app.ActivityThread.main(ActivityThread.java:5305)
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:922)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:717)
"Heap thread pool worker thread 0" prio=5 tid=2 Native (still starting up)
| group="" sCount=1 dsCount=0 obj=0x0 self=0xab1bffd0
| sysTid=24316 nice=0 cgrp=apps sched=0/0 handle=0xab3f9a28
| state=S schedstat=( 7943593 7965519 46 ) utm=0 stm=0 core=4 HZ=100
| stack=0xf4ca7000-0xf4ca9000 stackSize=1020KB
| held mutexes=
kernel: __switch_to+0x70/0x7c
kernel: futex_wait_queue_me+0xd4/0x12c
kernel: futex_wait+0xe0/0x1d4
kernel: do_futex+0xc8/0x8d0
kernel: compat_SyS_futex+0xd0/0x14c
kernel: cpu_switch_to+0x48/0x4c
native: #00 pc 0000f618 /system/lib/libc.so (syscall+28)
native: #01 pc 000a9487 /system/lib/libart.so (art::ConditionVariable::Wait(art::Thread*)+82)
native: #02 pc 00230897 /system/lib/libart.so (art::ThreadPool::GetTask(art::Thread*)+50)
native: #03 pc 0023083d /system/lib/libart.so (art::ThreadPoolWorker::Run()+52)
native: #04 pc 00231079 /system/lib/libart.so (art::ThreadPoolWorker::Callback(void*)+52)
native: #05 pc 00012f1b /system/lib/libc.so (__pthread_start(void*)+30)
native: #06 pc 00010fdf /system/lib/libc.so (__start_thread+6)
(no managed stack frames)
"Heap thread pool worker thread 1" prio=5 tid=3 Native (still starting up)
| group="" sCount=1 dsCount=0 obj=0x0 self=0xab19bb18
| sysTid=24317 nice=0 cgrp=apps sched=0/0 handle=0xab19ae08
| state=S schedstat=( 7940266 9912290 36 ) utm=0 stm=0 core=4 HZ=100
| stack=0xf4ba5000-0xf4ba7000 stackSize=1020KB
| held mutexes=
kernel: __switch_to+0x70/0x7c
kernel: futex_wait_queue_me+0xd4/0x12c
kernel: futex_wait+0xe0/0x1d4
kernel: do_futex+0xc8/0x8d0
kernel: compat_SyS_futex+0xd0/0x14c
kernel: cpu_switch_to+0x48/0x4c
native: #00 pc 0000f618 /system/lib/libc.so (syscall+28)
native: #01 pc 000a9487 /system/lib/libart.so (art::ConditionVariable::Wait(art::Thread*)+82)
native: #02 pc 00230897 /system/lib/libart.so (art::ThreadPool::GetTask(art::Thread*)+50)
native: #03 pc 0023083d /system/lib/libart.so (art::ThreadPoolWorker::Run()+52)
native: #04 pc 00231079 /system/lib/libart.so (art::ThreadPoolWorker::Callback(void*)+52)
native: #05 pc 00012f1b /system/lib/libc.so (__pthread_start(void*)+30)
native: #06 pc 00010fdf /system/lib/libc.so (__start_thread+6)
(no managed stack frames)
"Heap thread pool worker thread 2" prio=5 tid=4 Native (still starting up)
| group="" sCount=1 dsCount=0 obj=0x0 self=0xab3530a8
| sysTid=24318 nice=0 cgrp=apps sched=0/0 handle=0xab3539c0
| state=S schedstat=( 4911303 7280680 38 ) utm=0 stm=0 core=5 HZ=100
| stack=0xf4aa3000-0xf4aa5000 stackSize=1020KB
| held mutexes=
kernel: __switch_to+0x70/0x7c
kernel: futex_wait_queue_me+0xd4/0x12c
kernel: futex_wait+0xe0/0x1d4
kernel: do_futex+0xc8/0x8d0
kernel: compat_SyS_futex+0xd0/0x14c
kernel: cpu_switch_to+0x48/0x4c
native: #00 pc 0000f618 /system/lib/libc.so (syscall+28)
native: #01 pc 000a9487 /system/lib/libart.so (art::ConditionVariable::Wait(art::Thread*)+82)
native: #02 pc 00230897 /system/lib/libart.so (art::ThreadPool::GetTask(art::Thread*)+50)
native: #03 pc 0023083d /system/lib/libart.so (art::ThreadPoolWorker::Run()+52)
native: #04 pc 00231079 /system/lib/libart.so (art::ThreadPoolWorker::Callback(void*)+52)
native: #05 pc 00012f1b /system/lib/libc.so (__pthread_start(void*)+30)
native: #06 pc 00010fdf /system/lib/libc.so (__start_thread+6)
(no managed stack frames)
日志較多脐区,截取一部分,因為我們要分析的是main線程她按,所以丟掉部分線程代碼并不影響我們分析牛隅。
每一段都是一個線程,當然我們還是看main線程尤溜。通過分析發(fā)現(xiàn)突破口在這里:
native: #06 pc 00082b53 /system/lib/libandroid_runtime.so (???)
native: #07 pc 00a80891 /system/framework/arm/boot.oat (Java_android_os_BinderProxy_transactNative__ILandroid_os_Parcel_2Landroid_os_Parcel_2I+144)
at android.os.BinderProxy.transactNative(Native method)
at android.os.BinderProxy.transact(Binder.java:496)
at android.location.ILocationManager$Stub$Proxy.getFromLocation(ILocationManager.java:777)
at android.location.Geocoder.getFromLocation(Geocoder.java:133)
at bonree.com.bonree.agent.android.harvest.f.a(unavailable:-1)
at bonree.com.bonree.agent.android.harvest.j.onLocationChanged(unavailable:-1)
at android.location.LocationManager$ListenerTransport._handleMessage(LocationManager.java:281)
at android.location.LocationManager$ListenerTransport.access$000(LocationManager.java:210)
at android.location.LocationManager$ListenerTransport$1.handleMessage(LocationManager.java:226)
at android.os.Handler.dispatchMessage(Handler.java:102)
at android.os.Looper.loop(Looper.java:135)
at android.app.ActivityThread.main(ActivityThread.java:5305)
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:922)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:717)
可以看到程序調用了Geocoder類的getFromLocation方法倔叼,難道系統(tǒng)api也有bug?帶著疑問宫莱,我們看下Geocoder的源碼丈攒,如下:
從官方文檔的介紹來看,getFromLocation方法需要通過網(wǎng)絡查找來獲取結果,最好在主線程之外的線程來調用這個方法巡验。所以际插,最可能的原因就是我們程序在主線程調用了這個方法,然后移步到程序調用的地方显设,發(fā)現(xiàn)如下代碼
public final void a(Location var1) {
if(var1 == null) {
this.p.d("Location must not be null");
} else {
Geocoder var2 = new Geocoder(this.q);
List var3 = null;
try {
var3 = var2.getFromLocation(var1.getLatitude(), var1.getLongitude(), 1);
} catch (IOException var4) {
this.p.d("Unable to geocode location: " + var4.toString());
}
if(var3 != null && var3.size() != 0) {
Address var5;
if((var5 = (Address)var3.get(0)) != null) {
String var7 = var5.getCountryCode();
String var6 = var5.getAdminArea();
if(var7 != null && var6 != null) {
if(var7 == null || var6 == null) {
this.p.d("Country code and administrative region are required.");
}
this.l();
}
}
}
}
}
原來確實是程序在主線程調用了此方法框弛,導致主線程被阻塞,發(fā)生的ANR.