这个问题的是我在工作中遇到的。不是遇到这个问题,我还真不知道这个系统提供的API还能导致ANR。
由于anr这种在Android开发中经常遇到,我这边也按照排查问题的思路记录一下anr的定位方法。
1.首先查询log日志,使用“ANR in”找出ANR的地方(ActivityManager会打印报错信息:如下)
11-09 12:27:23.871 E/ActivityManager( 3456): ANR in com.xxxxx.xxxxxx (com.xxxxx.xxxxxx/.MainActivity)
(产生ANR的进程号)
11-09 12:27:23.871 E/ActivityManager( 3456): PID: 17590
产生ANR的原因有这些:
1.输入事件(按键和触摸事件)5s内没被处理: Input event dispatching timed out
2.BroadcastReceiver的事件(onRecieve方法)在规定时间内没处理完(前台广播为10s,后台广播为60s):Timeout of broadcast BroadcastRecord
3.service 前台20s后台200s未完成启动 Timeout executing service
4.ContentProvider的publish在10s内没进行完:timeout publishing content providers
(产生ANR的原因)
11-09 12:27:23.871 E/ActivityManager( 3456): Reason: Input dispatching timed out (Waiting to send key event because the focused window has not finished processing all of the input events that were previously delivered to it. Outbound queue length: 0. Wait queue length: 1.)
11-09 12:27:23.871 E/ActivityManager( 3456): Load: 16.17 / 16.13 / 16.52
(产生ANR时CPU使用情况)
11-09 12:27:23.871 E/ActivityManager( 3456): CPU usage from 0ms to 7464ms later (2020-11-09 12:27:16.371 to 2020-11-09 12:27:23.834):
11-09 12:27:23.871 E/ActivityManager( 3456): 93% 17590/com.xxxxx.xxxxxx: 86% user + 6.6% kernel / faults: 18916 minor 163 major
11-09 12:27:23.871 E/ActivityManager( 3456): 23% 4773/com.xxxx.lafite.srtnj.speechserver:SkyLafiteService: 17% user + 6.6% kernel / faults: 851 minor 37 major
11-09 12:27:23.871 E/ActivityManager( 3456): 22% 3456/system_server: 11% user + 11% kernel / faults: 1799 minor 88 major
11-09 12:27:23.871 E/ActivityManager( 3456): 18% 3936/com.xxxx.movieplatform: 13% user + 5.3% kernel / faults: 967 minor 85 major
11-09 12:27:23.871 E/ActivityManager( 3456): 18% 3283/android.hardware.audio@2.0-service: 14% user + 3.6% kernel
11-09 12:27:23.871 E/ActivityManager( 3456): 9.4% 5688/com.xxxx.de: 3.2% user + 6.2% kernel / faults: 1220 minor 43 major
11-09 12:27:23.871 E/ActivityManager( 3456): 6.2% 3295/surfaceflinger: 2.8% user + 3.4% kernel / faults: 356 minor
11-09 12:27:23.871 E/ActivityManager( 3456): 4.2% 3818/com.xxxx.system: 2.8% user + 1.4% kernel / faults: 612 minor 14 major
11-09 12:27:23.871 E/ActivityManager( 3456): 0% 14203/ntfs-3g: 0% user + 0% kernel / faults: 5883 minor
11-09 12:27:23.871 E/ActivityManager( 3456): 2.8% 1705/mmcqd/0: 0% user + 2.8% kernel
11-09 12:27:23.871 E/ActivityManager( 3456): 2.4% 3333/tvserver: 1.3% user + 1% kernel
11-09 12:27:23.871 E/ActivityManager( 3456): 2.2% 386/ksmd: 0% user + 2.2% kernel
通过上述信息的解读,这个anr是com.xxxxx.xxxxxx报出来的。属于一个输入时间导致的ANR。结合产生ANR时CPU的使用情况,可以判断出这个属于第一种情况。
1.如果发生ANR的进程CPU占用较高,如到了80%或90%以上,则可以怀疑是应用内一些代码不合理消耗掉了CPU资源,比如死循环或者一些算法库进行大量高精度复杂运算导致CPU长期占用较高,这就要结合trace和ANR前后的log进一步分析了。
2.如果某些进程的CPU占用百分比较高,几乎占用了所有CPU资源,而发生ANR的进程CPU占用为0%或非常低,则认为CPU资源被占用,进程没有被分配足够的资源,从而发生了ANR。这种情况多数可以认为是系统状态的问题,并不是由本应用造成的。
3.如果CPU总用量不高,那么很有可能是一些耗时操作或者锁的问题使主线程被阻塞 ,导致ANR。
4.如果iowait 占用率过高,很可能是系统等待I/O耗时操作,导致ANR。
2.在通过trace文件做进一步的分析:在设备的/data/anr路劲下有trace.txt文件,打开我们会看到如下显示:
具体怎么那这个trace文件请自行百度
(进程号) (发生ANR的具体时间)
----- pid 17590 at 2020-11-09 12:27:16 -----
(进程名/包名)
Cmd line: com.xxxxx.xxxxxx
(设备信息)
Build fingerprint: 'Xxxx/xxxx/nt72671D_a32:8.0.0/OPR6.170623.012/020.011.070:user/dev-keys'
ABI: 'arm'
Build type: optimized
Zygote loaded classes=4676 post zygote classes=3029
Intern table: 45946 strong; 148 weak
JNI: CheckJNI is off; globals=640 (plus 46 weak)
Libraries: /system/lib/libandroid.so /system/lib/libcompiler_rt.so /system/lib/libjavacrypto.so /system/lib/libjnigraphics.so /system/lib/libmedia_jni.so /system/lib/libsoundpool.so /system/lib/libwebviewchromium_loader.so /vendor/lib/libnvtmedia_jni.so libjavacore.so libopenjdk.so (10)
Heap: 44% free, 15MB/28MB; 316760 objects
.
.
.
DALVIK THREADS (74):
//下面一行说明了线程名称、daemon表示守护进程,线程的优先级(默认5)、线程锁id和线程状态,
//线程名称是启动线程的时候手动指明的,这里的main标识是主线程,是Android自动设定的
//一个线程名称,如果是自己手动创建的线程,一般会被命名成“Thread-xx”的格式,其中xx是
//线程id,它只增不减不会被复用;注意这其中的tid不是线程的id,它是一个在Java虚拟机中用
//来实现线程锁的变量,随着线程的增减,这个变量的值是可能被复用的;
(守护线程)
"Signal Catcher" daemon prio=5 tid=3 Runnable
| group="system" sCount=0 dsCount=0 flags=0 obj=0x12dc0270 self=0xae1dac00
| sysTid=17596 nice=0 cgrp=default sched=0/0 handle=0xa41fe970
| state=R schedstat=( 36508167 5245335 178 ) utm=1 stm=2 core=3 HZ=100
| stack=0xa4104000-0xa4106000 stackSize=1006KB
| held mutexes= "mutator lock"(shared held)
native: #00 pc 002c43d7 /system/lib/libart.so (_ZN3art15DumpNativeStackERNSt3__113basic_ostreamIcNS0_11char_traitsIcEEEEiP12BacktraceMapPKcPNS_9ArtMethodEPv+130)
native: #01 pc 00355959 /system/lib/libart.so (_ZNK3art6Thread9DumpStackERNSt3__113basic_ostreamIcNS1_11char_traitsIcEEEEbP12BacktraceMapb+200)
native: #02 pc 00351e2b /system/lib/libart.so (_ZNK3art6Thread4DumpERNSt3__113basic_ostreamIcNS1_11char_traitsIcEEEEbP12BacktraceMapb+34)
native: #03 pc 003696cf /system/lib/libart.so (_ZN3art14DumpCheckpoint3RunEPNS_6ThreadE+650)
native: #04 pc 00363359 /system/lib/libart.so (_ZN3art10ThreadList13RunCheckpointEPNS_7ClosureES2_+320)
native: #05 pc 00362eb9 /system/lib/libart.so (_ZN3art10ThreadList4DumpERNSt3__113basic_ostreamIcNS1_11char_traitsIcEEEEb+536)
native: #06 pc 00362b73 /system/lib/libart.so (_ZN3art10ThreadList14DumpForSigQuitERNSt3__113basic_ostreamIcNS1_11char_traitsIcEEEE+650)
native: #07 pc 00340277 /system/lib/libart.so (_ZN3art7Runtime14DumpForSigQuitERNSt3__113basic_ostreamIcNS1_11char_traitsIcEEEE+122)
native: #08 pc 00347147 /system/lib/libart.so (_ZN3art13SignalCatcher13HandleSigQuitEv+1130)
native: #09 pc 00346391 /system/lib/libart.so (_ZN3art13SignalCatcher3RunEPv+240)
native: #10 pc 00047e2f /system/lib/libc.so (_ZL15__pthread_startPv+22)
native: #11 pc 0001b1cd /system/lib/libc.so (__start_thread+32)
(no managed stack frames)
(main标识是主线程)
"main" prio=5 tid=1 Native
//group是线程组名称。sCount是此线程被挂起的次数,dsCount是线程被调试器挂起的次数,
//当一个进程被调试后,sCount会重置为0,调试完毕后sCount会根据是否被正常挂起增长,
//但是dsCount不会被重置为0,所以dsCount也可以用来判断这个线程是否被调试过。obj表示
//这个线程的Java对象的地址,self表示这个线程Native的地址。
(线程组名称)(被挂起的次数) (被调试器挂起的次数)
| group="main" sCount=1 dsCount=0 flags=1
(Java对象的地址) (Native的地址/方法的地址)
obj=0x72d39580 self=0xae1da000
//此后是线程的调度信息,sysTid是Linux下的内核线程id,nice是线程的调度优先级,
//sched分别标志了线程的调度策略和优先级,cgrp是调度属组,handle是线程的处理函数地址。
(内核线程id) (调度优先级) (调度策略和优先级) (handle是线程的处理函数地址)
| sysTid=17590 nice=-10 cgrp=default sched=0/0 handle=0xb1d314ac
//线程当前上下文信息,state是调度状态;schedstat从 /proc/[pid]/task/[tid]/schedstat读出,
//三个值分别表示线程在cpu上执行的时间、线程的等待时间和线程执行的时间片长度,有的
//android内核版本不支持这项信息,得到的三个值都是0;utm是线程用户态下使用的时间
//值(单位是jiffies);stm是内核态下的调度时间值;core是最后执行这个线程的cpu核的序号。
(用户态下使用的时间) (内核态下的调度时间值)
| state=S schedstat=( 54617602003 18518257583 163633 ) utm=3986 stm=1474 core=0 HZ=100
| stack=0xbde84000-0xbde86000 stackSize=8MB
| held mutexes=
kernel: (couldn't read /proc/self/task/17590/stack)
//线程的调用栈信息(这里可查看导致ANR的代码调用流程,分析ANR最重要的信息)
native: #00 pc 00049cec /system/lib/libc.so (fstatat+12)
native: #01 pc 00015cb7 /system/lib/libopenjdk.so (Java_java_io_UnixFileSystem_getBooleanAttributes0+42)
native: #02 pc 0001b3f5 /system/framework/arm/boot.oat (Java_java_io_UnixFileSystem_getBooleanAttributes0__Ljava_lang_String_2+92)
at java.io.UnixFileSystem.getBooleanAttributes0(Native method)
at java.io.UnixFileSystem.getBooleanAttributes(UnixFileSystem.java:243)
at java.io.File.isFile(File.java:870)
at com.xxxxx.xxxxxx.data.FileBrowserManager.startPlayer(FileBrowserManager.java:820)
at com.xxxxx.xxxxxx.data.FileBrowserManager.load(FileBrowserManager.java:204)
at com.xxxxx.xxxxxx.uiview.specificlayout.MediaFileLayout.handleItemClickEvent(MediaFileLayout.java:754)
at com.xxxxx.xxxxxx.uiview.specificlayout.MediaFileLayout.-wrap2(MediaFileLayout.java:-1)
at com.xxxxx.xxxxxx.uiview.specificlayout.MediaFileLayout$4.onOtherKeyEvent(MediaFileLayout.java:182)
at com.xxxx.ui.newrecycleview.NewRecycleLayout.onOtherKeyEvent(NewRecycleLayout.java:1117)
at android.support.v7.widget.NewRecycleAdapter$3.onKey(NewRecycleAdapter.java:271)
at android.view.View.dispatchKeyEvent(View.java:11654)
at android.view.ViewGroup.dispatchKeyEvent(ViewGroup.java:1829)
通过以上的信息,基本上可以确定是at java.io.File.isFile(File.java:870)这里出来问题。
自此,ANR的原因算是找到了。
按照找到的原因,我打开项目里面的代码,发现这里的代码被修改过。以前的代码
if(file == null || !file.exists()){
//同事改动的代码改成了 "file == null || !file.isFile()"
}
索性提交这位修改的同事还在,跑过去求教才知道,原来使用file.exists()的时候,这里也报出了anr,所以他也是一顿猛操作,查看了好多资料。最后改成了file. isFile()。据他的结论,这个file. isFile()的性能会好一些。这个原因没有说服我,因为至少换了之后,anr还是依然的存在。可能问题不在这里。
我仔细一想这不是系统原生的API吗,为什么原生的API会导致这样的问题,难道是google的程序员代码写的不好?这个的确有点超出自己的知识体系了,不过还好会百度+Google。查阅好多网页后,发现也有好多人遇到我这样相似的问题,这个解释的比较全一些:
https://www.itdaan.com/tw/1398d5e7c0a01428fdb0cd68ce921e43
getBooleanAttributes0 calls stat (or stat64, if available). If you have the OpenJDK source code, this is listed in file jdk/src/solaris/native/java/io/UnixFileSystem_md.c.getBooleanAttributes0調用stat(或stat64,如果可用)。如果您有OpenJDK源代碼,則會在文件jdk / src / solaris / native / java / io / UnixFileSystem_md.c中列出。
So the real question is, why is stat frozen? Is the file being accessed a network file on a server that's down, for example? If this is a reproducible problem, you may wish to use strace to attach to the Java process, just prior to the freezing. Then look in the output for calls to stat, to see what's being accessed.
所以真正的問題是,為什么stat凍結?例如,在被關閉的服務器上訪問文件是否是網絡文件?如果這是一個可重現的問題,您可能希望在凍結之前使用strace附加到Java進程。然后在輸出中查看對stat的調用,以查看正在訪問的內容。
看到这段话,虽然没有完全明白。但是我相信我大概找到问题的真正原因了。不过比较遗憾他说的解决方案,我不是很懂。
最后,我又全局的看了一下这个代码的意图。这里只是想判断文件对象是否为空。本着快速解决问题的宗旨。我最后做了一个小修改。把这里改成"file. file.length() > 0"。不过还是不放心,还麻烦测试对这个场景暴力测试了一番,目前没有出现异常。