1、背景
项目中有一项需求是能扫描U盘里的图片,图片存在于文件夹里;要求文件夹最多有65536个,文件夹层级最多8级。在执行用例测试的时候出现了ANR。
2、Android下的ANR
根据ActivityManagerService里的代码,Android下的ANR有如下几种:
名称\类型 | 前台 | 后台 |
---|---|---|
input | 5s | |
ContentProvider | 10s | |
Broadcast | 10s | 60s |
Service | 20s | 200s |
3、ANR日志中的关键字
一般来说,发生ANR都是由于UI主线程发生了上述定义的几种情况才会抛出ANR。所以,分析日志的时候只需要分析主线程即main
线程的日志。Java线程即c++线程对应关系如下:
java线程状态 | cpp线程状态 | 说明 |
---|---|---|
TERMINATED | ZOMBIE | 线程死亡,终止运行 |
RUNNABLE | RUNNING/RUNNABLE | 线程可运行或正在运行 |
TIMED WAITING | TIMED WAIT | 执行了带有超时参数的wait、sleep或join函数 |
BLOCKED | MONITOR | 线程阻塞,等待获取对象锁 |
WAITING | WAIT | 执行了无超时参数的wait函数 |
NEW | INITIALIZING | 新建,正在初始化,为其分配资源 |
NEW | STARTING | 新建,正在启动 |
RUNNABLE | NATIVE | 正在执行JNI本地函数 |
WAITING | VMWAIT | 正在等待VM资源 |
RUNNABLE | SUSPENDED | 线程暂停,通常是由于GC或debug被暂停 |
UNKNOWN | 未知状态 |
4、日志分析
出现问题时间的日志
03-27 19:58:29.720 484 574 I WindowManager: Input event dispatching timed out sending to packagename/packagename.PhotoListActivity. Reason: 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: 2. Wait queue head age: 6033.0ms.
日志已经很清楚地说明对点击事件的响应超过了5s,抛出了ANR。这个时候,系统开始dump此时此刻各进程的情况,大约过了30秒dump出以下信息:
03-27 19:58:46.992 484 574 I chatty : uid=1000(system) InputDispatcher expire 18 lines
03-27 19:58:47.001 484 574 I ActivityManager: Done dumping
03-27 19:58:47.024 484 574 E ActivityManager: ANR in packagename (packagename/.media_photo.view.PhotoListActivity)
03-27 19:58:47.024 484 574 E ActivityManager: PID: 20375
03-27 19:58:47.024 484 574 E ActivityManager: 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: 2. Wait queue head age: 6033.0ms.)
03-27 19:58:47.024 484 574 E ActivityManager: Parent: packagenmae/.media_photo.view.PhotoListActivity
03-27 19:58:47.024 484 574 E ActivityManager: Load: 7.25 / 6.45 / 6.11
03-27 19:58:47.024 484 574 E ActivityManager: CPU usage from 0ms to 17169ms later (2023-03-27 19:58:29.831 to 2023-03-27 19:58:47.001):
03-27 19:58:47.024 484 574 E ActivityManager: 95% 484/system_server: 31% user + 64% kernel / faults: 21172 minor
03-27 19:58:47.024 484 574 E ActivityManager: 90% 20375/packagename: 87% user + 3.2% kernel / faults: 21420 minor
03-27 19:58:47.024 484 574 E ActivityManager: 22% 1615/com.tencent.supercar:speechserver: 19% user + 3.7% kernel / faults: 27547 minor……
到这里,就可以确定无疑,发生了ANR。需要对照ANR日志进一步分析,查看20375进程对应dump出的日志:
----- pid 20375 at 2023-03-27 19:58:30 -----
Cmd line: packagename
Build fingerprint: ‘SZ-IGENTAI-FX12’
ABI: ‘arm’
Build type: optimized
Zygote loaded classes=9110 post zygote classes=2404
Dumping registered class loaders
……
//以下是截取的部分对应时间点线程dump信息
“main” prio=5 tid=1 Native
| group=“main” sCount=1 dsCount=0 flags=1 obj=0x725003d8 self=0xf0e5ce00
| sysTid=20375 nice=-10 cgrp=default sched=0/0 handle=0xf13c0dc0
| state=R schedstat=( 96440151896 8274881069 65858 ) utm=9314 stm=329 core=1 HZ=100
| stack=0xff6db000-0xff6dd000 stackSize=8192KB
| held mutexes=
kernel: (couldn’t read /proc/self/task/20375/stack)
native: #00 pc 00033e78 /system/lib/libsqlite.so (sqlite3VdbeSorterReset+788)
native: #01 pc 0003371d /system/lib/libsqlite.so (sqlite3VdbeFreeCursor+44)
native: #02 pc 00032185 /system/lib/libsqlite.so (sqlite3VdbeHalt+104)
native: #03 pc 00016d1f /system/lib/libsqlite.so (sqlite3VdbeReset+6)
native: #04 pc 00016c9b /system/lib/libsqlite.so (sqlite3_reset+42)
native: #05 pc 000aaf91 /system/lib/libandroid_runtime.so (android::nativeExecuteForCursorWindow(_JNIEnv*, _jclass*, long long, long long, long long, int, int, unsigned char)+432)
at android.database.sqlite.SQLiteConnection.nativeExecuteForCursorWindow(Native method)
at android.database.sqlite.SQLiteConnection.executeForCursorWindow(SQLiteConnection.java:942)
at android.database.sqlite.SQLiteSession.executeForCursorWindow(SQLiteSession.java:838)
at android.database.sqlite.SQLiteQuery.fillWindow(SQLiteQuery.java:62)
at android.database.sqlite.SQLiteCursor.fillWindow(SQLiteCursor.java:161)
at android.database.sqlite.SQLiteCursor.onMove(SQLiteCursor.java:131)
at android.database.AbstractCursor.moveToPosition(AbstractCursor.java:249)
at android.database.AbstractCursor.moveToNext(AbstractCursor.java:281)
at packagename.media_usb.model.MediaStorageDataModel.queryAllPhotosFolder(MediaStorageDataModel.java:342)
at packagename.media_photo.presenter.PhotoListPresenter.getFolderList(PhotoListPresenter.java:421)
at packagename.media_photo.presenter.PhotoListPresenter.getFirstFolderList(PhotoListPresenter.java:397)
at packagename.media_photo.presenter.PhotoListPresenter.reqSwitchToFolderList(PhotoListPresenter.java:301)
at packagename.media_photo.view.PhotoListFragment.showPhotoList(PhotoListFragment.java:619)
at packagename.media_photo.view.PhotoListFragment.onClick(PhotoListFragment.java:654)
at android.view.View.performClick(View.java:7142)
at android.view.View.performClickInternal(View.java:7119)
at android.view.View.access 3500 ( V i e w . j a v a : 803 ) a t a n d r o i d . v i e w . V i e w 3500(View.java:803) at android.view.View 3500(View.java:803)atandroid.view.ViewPerformClick.run(View.java:27357)
at android.os.Handler.handleCallback(Handler.java:883)
at android.os.Handler.dispatchMessage(Handler.java:100)
at android.os.Looper.loop(Looper.java:214)
at android.app.ActivityThread.main(ActivityThread.java:7356)
at java.lang.reflect.Method.invoke(Native method)
at com.android.internal.os.RuntimeInitKaTeX parse error: Expected 'EOF', got '#' at position 533: …ack) native: #̲00 pc 0005a7b0 …HeapTaskDaemon.runInternal(Daemons.java:523)
at java.lang.Daemons$Daemon.run(Daemons.java:137)
at java.lang.Thread.run(Thread.java:919)
“ReferenceQueueDaemon” daemon prio=5 tid=9 Waiting
| group=“system” sCount=1 dsCount=0 flags=1 obj=0x147403c8 self=0xe5d7ca00
| sysTid=20394 nice=4 cgrp=default sched=0/0 handle=0xc6f0a230
| state=S schedstat=( 3577209 2217792 17 ) utm=0 stm=0 core=2 HZ=100
| stack=0xc6e07000-0xc6e09000 stackSize=1040KB
| held mutexes=
……
“FinalizerDaemon” daemon prio=5 tid=10 Waiting
| group=“system” sCount=1 dsCount=0 flags=1 obj=0x14740440 self=0xe5d7e600
| sysTid=20395 nice=4 cgrp=default sched=0/0 handle=0xc6e01230
| state=S schedstat=( 3561458 482543 17 ) utm=0 stm=0 core=2 HZ=100
| stack=0xc6cfe000-0xc6d00000 stackSize=1040KB
| held mutexes=
at java.lang.Object.wait(Native method)
……
ReferenceQueueDaemon、FinalizerDaemon这两个进程都是系统被创建之后用于GC的线程,这两个线程处于等待状态;同时UI主线程在进行上万个的cursor查询操作,界面又通过glide加载了上万张图片。结合内存数据推测这个时候系统应该处于内存待回收而UI主线程执行了长耗时操作的状态。加载上万张图片暂不考虑优化的话,只能想办法减少UI主线程执行耗时时间。
5、解决方案
通过日志分析,已经知道定位了问题,只需要把数据库查询操作放到线程里,通过回调刷新界面即可。这里就不贴代码了。
解决ANR最重要的办法是要拿到ANR日志,按图索骥地修改。