关于File.isFile导致的anr

这个问题的是我在工作中遇到的。不是遇到这个问题,我还真不知道这个系统提供的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"。不过还是不放心,还麻烦测试对这个场景暴力测试了一番,目前没有出现异常。

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 206,968评论 6 482
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 88,601评论 2 382
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 153,220评论 0 344
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 55,416评论 1 279
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 64,425评论 5 374
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 49,144评论 1 285
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 38,432评论 3 401
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 37,088评论 0 261
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 43,586评论 1 300
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 36,028评论 2 325
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 38,137评论 1 334
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,783评论 4 324
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 39,343评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,333评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,559评论 1 262
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 45,595评论 2 355
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,901评论 2 345

推荐阅读更多精彩内容

  • ANR问题,相信是每位开发日常都会遇到的问题,对于这类问题的分析,按照官方的推荐,或网络博客的总结思路能解决一定的...
    tiger桂阅读 17,852评论 5 28
  • 标签 :Android ANR traces文件 1、ANR定义及分类 ANR:Application Not R...
    曾是放牛娃阅读 5,439评论 0 4
  • 在我们平时开发的过程中,常常测试的同事会告诉我们在运行的时候偶现ANR错误或者monkey测试时,出现了AN...
    Android开发_Hua阅读 4,215评论 0 2
  • 1 最近看到一个测试的log 如下:查看logcat 的log 01-18 18:04:10.165 697 ...
    超__越阅读 7,463评论 3 1
  • 久违的晴天,家长会。 家长大会开好到教室时,离放学已经没多少时间了。班主任说已经安排了三个家长分享经验。 放学铃声...
    飘雪儿5阅读 7,495评论 16 22