当前位置:   article > 正文

你真的会解决android ANR 问题吗?_system_server anr

system_server anr

前言

​ 还记得之前写过一篇关于ANR 的介绍,现在看来,那个只是皮毛。现实中遇到应用或系统ANR 的问题,是很难解决的。下面进入正题,来详细了解下如何解决。

一. ANR 分析步骤

Log分析:

  • 1.首先,需要定位ANR发生的时间点,从event-log查找“am_ANR”关键字可以定位。
  • 2.其次,从main-log(system-log)中查找“ANR in”关键字确认ANR具体的信息。
  • 3.信息包含:ANR发生的进程名、进程号。ANR发生的原因。ANR发生的时候,当时的进程cpu占用情况,同时具体进程占用的上层和kernel层资源情况。ANR发生的时候cpu的负载情况。IOWAIT情况以及总的CPU使用情况。
  • 4.进一步查看trace-log,了解进程的堆栈信息来判断ANR的原因。(一定要结合trace log 看,否则像一些死锁,进程堆栈都会发现不了)

1.intput-ANR 大致定位

在这里插入图片描述

2.ANR 类问题大致定位流程

在这里插入图片描述

3.APP ANR 问 题定位大致流程。

在这里插入图片描述

4. 导致ANR 的原因

1.应用导致
a. 函数阻塞:如死循环、主线程IO、处理大数据
b. 锁出错:主线程等待子线程的锁
c. 内存紧张:系统分配给一个应用的内存是有上限的,长期处于内存紧张,会导致频繁内存交换,进而导致应用的一些操作超时
  • 1
  • 2
  • 3
2.系统导致
a. CPU被抢占:一般来说,前台在玩游戏,可能会导致你的后台广播被抢占CPU
b. 系统服务无法及时响应:比如获取系统联系人等,系统的服务都是Binder机制,服务能力也是有限的,有可能系统服务长时间不响应导致ANR
c. 其他应用占用的大量内存
  • 1
  • 2
  • 3

5.线程的状态

Thread.java中的定义Thread.cpp中的定义说明
TERMINATEDZOMBIE线程死亡,终止运行
RUNNABLERUNNING/RUNNABLE线程可运行或正在运行
TIMED_WAITINGTIMED_WAIT执行了带有超时参数的wait、sleep、join函数
BLOCKEDMONITOR线程阻塞,等待获取对象锁
WAITINGWAIT执行了无超时参数的wait函数
NEWINITIALIZING新建,正在初始化,为其分配资源
NEWSTARTING新建,正在启动
RUNNABLENATIVE正在执行JNI本地函数
WAITINGVMWAIT正在等待VM资源
RUNNABLESUSPENDED线程暂停,通常是由于GC或debug暂停
UNKNOWN

二.ANR 关键字

1. event log 中“am_ANR” 关键字,main-log (system-log)中查看“ANR in” 关键字。

2.binder_sample

功能说明: 监控每个进程的主线程的 binder transaction 的耗时情况, 当超过阈值时,则输出相应的目标调用信息,默认 1000ms 打开。log格式:52004 binder_sample(descriptor|3),(method_num|1|5),(time|1|3),(blocking_package|3),(sample_percent|1|6)例:binder_sample:[android.app.IActivityManager,35,2900,android.process.media,5]从上面的 log 中可以得出:主线程2754执行android.app.IActivityManager接口,所对应方法code =35(即STOP_SERVICE_TRANSACTION),所花费时间为2900ms.该block所在package为android.process.media,最后一个参数是sample比例.

3.Reason

在这里插入图片描述
CPU 负载。Load 关键字表明了最近 1 分钟、5 分钟、15 分钟内的 CPU 负载分别是0.23、0.09、0.05。CPU 最近 1 分钟的负载最具参考价值,因为 ANR 的超时限制基本都是 1分钟以内, 这可以近似的理解为 CPU 最近 1 分钟平均有 0.23 个任务要处理.CPU 使用统计时间段。CPU usage from XX to XX ago 关键字表明了这是在 ANR 发生之前一段时间内的 CPU 统计.

4.Binder

IPCThreadState: binder thread pool (15 threads) starved for 3630 ms
  • 1

功能说明:当 system_server 等进程的线程池使用完, 无空闲线程时, 则 binder 通信都处于饥饿状态, 则饥饿状态超过一定阈值则输出信息;

log 解析: system_server 进程的 线程池已满的持续长达 3630 ms.

5.JavaBinder: !!! FAILED BINDER TRANSACTION !!!

JavaBinder: !!! FAILED BINDER TRANSACTION !!!log 解析:binder 传输出错,有可能是传输的数据太大导致

6.Slow dispatch took

Looper : Slow dispatch took 92974ms main h=android.os.Handler c=com.android.server.locksettings.-$$Lambda$LockSettingsService$lWTrcqR9gZxL-pxwBbtvTGqAifU@4492f32 m=0
  • 1

log 解析:LockSettingsService 卡顿,耗时 92974ms

7.Kernel log

[101:kswapd0]lowmemorykiller: Killing ‘earchbox:search’ (3881), adj 900,

log 解析:lowmemorykiller都是从大kill到小,adj 越小说明系统 lowmemory 越严重。

8.Dropbox

Dropbox 中重点看 total,CPU 占用率、IOwait。对于 IOwait 来说,高于 5%其实就已经危险了,达到 10%就有很大几率产生 ANR 了,至于 IOwait 为什么会产生,基本上有三种情况:大文件读写(main-log 关键字: “inputstream”)内存整理(关键字:“kswapd0”、“lost ram”)系统 dump log(main-log 关键字:“dump”)。

9.kswapd0

在这里插入图片描述

swap分区的作用是当物理内存不足时,会将一部分硬盘当做虚拟内存来使用。kswapd0 占用过高是因为 物理内存不足,使用swap分区与内存换页操作交换数据,导致CPU占用过高。低内存时候,kswapd0会很高,同时也会影响到io此时,系统一般都会存在卡顿等现象,iowait也会存在异常。

在这里插入图片描述

10.held by thread

线程持有,一般我们在trace-log里边看到主线程存在held by thread XXX,可以根据XXX内容找到是哪个线程block了主线程
在这里插入图片描述

可以清楚的看到主线程和子线程互锁,从而发生死锁

11.talkWithDriver

线程状态为“Native”,且含有如下callstack:

IPCThreadState::waitForResponse–>IPCThreadState::talkWithDriver,

当trace-log中出现talkWithDriver关键字时,一般都是卡在了对端导致产生ANR,从而查看binder-info内容,以此定位对端信息。从对端thread的callstack中确认卡住的接口,并请对端相关的owner帮忙解决。

12.proc xxx

xxx为线程的id,定位binder-info线程时可以快速定位
在这里插入图片描述

关键字“outgoing transaction”

上述方法如果找不到binder对端。可以尝试在kernel_log中查找binder release的log(binder所在进程结束时会调用),例如:kernel_log[ 543.692215] .(6)[6750:kworker/6:1]binder: release 1035:1035 transaction 257798 out, still active

13.SurfaceFlinger卡住

SF hang Time > 40s(Service.sf.status值),sf hang,直接在”SYS_ANDROID_LOG”搜索”I watchdog”,看是否有“surfaceflinger hang”关键字

14.Zygote fork进程时卡住线程

状态为“Native”,确认callstack中有“Process.zygoteSendArgsAndGetResult”,对于Zygote fork进程时卡住的问题,一般是由于底层memory问题引起的,请检查是否有memory不足或者memory leak的问题

15.主要在log中出现上述信息,可以怀疑与memory有关,可以请求性能组协助分析!!!

日志关键log备注
SYS_MEMORY_INFO• MemAvailable: < 100M• SwapCached: > 150M
SYS_MEMORY_LOG[pid], score_adj, rss, rswp, pswpin, pswpout, pfmflt [681], -1000, 116, 4488, 34691, 0, 1216RSS+RSWAP > 500M
SYS_CPU_INFO/ANR_INFOKswapd0排名前3
KERNEL_LOG• [101:kswapd0]lowmemorykiller: Killing ‘earchbox:search’ (3881), adj 900, • cache 506156kB is below limit 430080kB for 14200kB above reserved\x0a • (decrease 1 level, amr_adj 900) • DMA free: … slab_unreclaimable:125920kBadj越小说明系统lowmemory越严重 < 100 (红色两个加起来,指明当前可用memory,越小说明系统lowmemory越严重)< 100M指明当前是否根据ZRAM 消耗值是否越级查杀进程,值越大越激进 ≥ 2 Alloc buffer fail ,疑似泄露 > 500M

16. trace 文件关键信息解释

发生ANR的时候,系统会产生一份anr日志文件(手机的/data/anr 目录下,文件名称可能各厂商不一样,业内大多称呼为trace文件),内含如下几项重要信息。

1.CPU 负载
Load: 2.62 / 2.55 / 2.25
CPU usage from 0ms to 1987ms later (2020-03-10 08:31:55.169 to 2020-03-10 08:32:17.156):
   41% 2080/system_server: 28% user + 12% kernel / faults: 76445 minor 180 major
   26% 9378/com.xiaomi.store: 20% user + 6.8% kernel / faults: 68408 minor 68 major
........省略N行.....
66% TOTAL: 20% user + 15% kernel + 28% iowait + 0.7% irq + 0.7% softirq
  • 1
  • 2
  • 3
  • 4
  • 5
  • 6

如上所示:

第一行:1、5、15 分钟内正在使用和等待使用CPU 的活动进程的平均数
第二行:表明负载信息抓取在ANR发生之后的0~1987ms。同时也指明了ANR的时间点:2020-03-10 08:31:55.169
中间部分:各个进程占用的CPU的详细情况
最后一行:各个进程合计占用的CPU信息。
  • 1
  • 2
  • 3
  • 4

名词解释:

a. user:用户态,kernel:内核态
b. faults:内存缺页,minor——轻微的,major——重度,需要从磁盘拿数据
c. iowait:IO使用(等待)占比
d. irq:硬中断,softirq:软中断
  • 1
  • 2
  • 3
  • 4

注意:

iowait占比很高,意味着有很大可能,是io耗时导致ANR,具体进一步查看有没有进程faults major比较多。

单进程CPU的负载并不是以100%为上限,而是有几个核,就有百分之几百,如4核上限为400%。

2.内存信息
Total number of allocations 476778  进程创建到现在一共创建了多少对象
Total bytes allocated 52MB 进程创建到现在一共申请了多少内存
Total bytes freed 52MB   进程创建到现在一共释放了多少内存
Free memory 777KB    不扩展堆的情况下可用的内存
Free memory until GC 777KB  GC前的可用内存
Free memory until OOME 383MB  OOM之前的可用内存
Total memory 当前总内存(已用+可用)
Max memory 384MB  进程最多能申请的内存
  • 1
  • 2
  • 3
  • 4
  • 5
  • 6
  • 7
  • 8

从含义可以得出结论:**Free memory until OOME **的值很小的时候,已经处于内存紧张状态。应用可能是占用了过多内存。

另外,除了trace文件中有内存信息,普通的eventlog日志中,也有内存信息(不一定打印)

04-02 22:00:08.195  1531  1544 I am_meminfo: [350937088,41086976,492830720,427937792,291887104]
  • 1

以上四个值分别指的是:Cached,Free,Zram,Kernel,Native

Cached+Free的内存代表着当前整个手机的可用内存,如果值很小,意味着处于内存紧张状态。一般低内存的判定阈值为:4G 内存手机以下阀值:350MB,以上阀值则为:450MB

ps:如果ANR时间点前后,日志里有打印onTrimMemory,也可以作为内存紧张的一个参考判断

3.堆栈
"main" prio=5 tid=1 Native
  | group="main" sCount=0 dsCount=0 flags=0 obj=0x727c02f8 self=0xb400007a2f210800
  | sysTid=339 nice=-10 cgrp=default sched=0/0 handle=0x7ab698d500
  | state=? schedstat=( 0 0 0 ) utm=0 stm=0 core=0 HZ=100
  | stack=0x7fc8197000-0x7fc8199000 stackSize=8192KB
  | held mutexes=
  at android.os.MessageQueue.nativePollOnce(Native method)
  at android.os.MessageQueue.next(MessageQueue.java:339)
  at android.os.Looper.loop(Looper.java:200)
  at android.app.ActivityThread.main(ActivityThread.java:8312)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:632)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1049)
  • 1
  • 2
  • 3
  • 4
  • 5
  • 6
  • 7
  • 8
  • 9
  • 10
  • 11
  • 12
  • 13

线程基本信息

线程优先级:prio=5 (主线程均是5)
线程ID: tid=1 主线程的id一般都是1
线程状态:Native :表示正在调用JNI
还有其他多种状态,表示发生ANR时主线程的状态
线程组名称:group=“main”
线程被挂起的次数:sCount=0
在等待GC时,有时候挂起的线程数量比较多
线程被调试器挂起的次数:dsCount=0
线程的java的对象地址:obj= 0x7682ab30
线程本身的Native对象地址:self=0x7bd3815c00线程调度信息:
  • 1
  • 2
  • 3
  • 4
  • 5
  • 6
  • 7
  • 8
  • 9
  • 10

线程优先级信息

Linux系统中内核线程ID: sysTid=6317与主线程的进程号相同
线程调度优先级:nice=-10
线程调度组:cgrp=default
线程调度策略和优先级:sched=0/0
线程处理函数地址:handle= 0x7c59fc8548
  • 1
  • 2
  • 3
  • 4
  • 5

线程状态信息

线程调度状态:state=S
线程在CPU中的执行时间、线程等待时间、线程执行的时间片长度:schedstat=(1009468742 32888019 224)
线程在用户态中的调度时间值:utm=91
线程在内核态中的调度时间值:stm=9
最后执行这个线程的CPU核序号:core=4
  • 1
  • 2
  • 3
  • 4
  • 5

线程堆栈信息

堆栈地址和大小:stack=0x7ff27e1000-0x7ff27e3000 stackSize=8MB
  • 1

三.ANR 经典案例

1.主线程无卡顿,处于正常状态堆栈

"main" prio=5 tid=1 Native
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x74b38080 self=0x7ad9014c00
  | sysTid=23081 nice=0 cgrp=default sched=0/0 handle=0x7b5fdc5548
  | state=S schedstat=( 284838633 166738594 505 ) utm=21 stm=7 core=1 HZ=100
  | stack=0x7fc95da000-0x7fc95dc000 stackSize=8MB
  | held mutexes=
  kernel: __switch_to+0xb0/0xbc
  kernel: SyS_epoll_wait+0x288/0x364
  kernel: SyS_epoll_pwait+0xb0/0x124
  kernel: cpu_switch_to+0x38c/0x2258
  native: #00 pc 000000000007cd8c  /system/lib64/libc.so (__epoll_pwait+8)
  native: #01 pc 0000000000014d48  /system/lib64/libutils.so (android::Looper::pollInner(int)+148)
  native: #02 pc 0000000000014c18  /system/lib64/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+60)
  native: #03 pc 00000000001275f4  /system/lib64/libandroid_runtime.so (android::android_os_MessageQueue_nativePollOnce(_JNIEnv*, _jobject*, long, int)+44)
  at android.os.MessageQueue.nativePollOnce(Native method)
  at android.os.MessageQueue.next(MessageQueue.java:330)
  at android.os.Looper.loop(Looper.java:169)
  at android.app.ActivityThread.main(ActivityThread.java:7073)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:536)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:876)
  • 1
  • 2
  • 3
  • 4
  • 5
  • 6
  • 7
  • 8
  • 9
  • 10
  • 11
  • 12
  • 13
  • 14
  • 15
  • 16
  • 17
  • 18
  • 19
  • 20
  • 21

上述主线程堆栈就是一个很正常的空闲堆栈,表明主线程正在等待新的消息。如果ANR日志里主线程是这样一个状态,那可能有两个原因:

  • 1.该ANR是CPU抢占或内存紧张等其他因素引起

  • 2.这份ANR日志抓取的时候,主线程已经恢复正常

    遇到这种空闲堆栈,可以去分析CPU、内存的情况。其次可以关注抓取日志的时间和ANR发生的时间是否相隔过久,时间过久这个堆栈就没有分析意义了。

2.主线程执行耗时操作

"main" prio=5 tid=1 Runnable
  | group="main" sCount=0 dsCount=0 flags=0 obj=0x72deb848 self=0x7748c10800
  | sysTid=8968 nice=-10 cgrp=default sched=0/0 handle=0x77cfa75ed0
  | state=R schedstat=( 24783612979 48520902 756 ) utm=2473 stm=5 core=5 HZ=100
  | stack=0x7fce68b000-0x7fce68d000 stackSize=8192KB
  | held mutexes= "mutator lock"(shared held)
  at com.example.test.MainActivity$onCreate$2.onClick(MainActivity.kt:20)——关键行!!!
  at android.view.View.performClick(View.java:7187)
  at android.view.View.performClickInternal(View.java:7164)
  at android.view.View.access$3500(View.java:813)
  at android.view.View$PerformClick.run(View.java:27640)
  at android.os.Handler.handleCallback(Handler.java:883)
  at android.os.Handler.dispatchMessage(Handler.java:100)
  at android.os.Looper.loop(Looper.java:230)
  at android.app.ActivityThread.main(ActivityThread.java:7725)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:526)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1034)
  • 1
  • 2
  • 3
  • 4
  • 5
  • 6
  • 7
  • 8
  • 9
  • 10
  • 11
  • 12
  • 13
  • 14
  • 15
  • 16
  • 17
  • 18

上述日志表明,主线程正处于执行状态,看堆栈信息可知不是处于空闲状态,发生ANR是因为一处click监听函数里执行了耗时操作。

3.主线程被锁阻塞

"main" prio=5 tid=1 Blocked
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x72deb848 self=0x7748c10800
  | sysTid=22838 nice=-10 cgrp=default sched=0/0 handle=0x77cfa75ed0
  | state=S schedstat=( 390366023 28399376 279 ) utm=34 stm=5 core=1 HZ=100
  | stack=0x7fce68b000-0x7fce68d000 stackSize=8192KB
  | held mutexes=
  at com.example.test.MainActivity$onCreate$1.onClick(MainActivity.kt:15)
  - waiting to lock <0x01aed1da> (a java.lang.Object) held by thread 3 ——————关键行!!!
  at android.view.View.performClick(View.java:7187)
  at android.view.View.performClickInternal(View.java:7164)
  at android.view.View.access$3500(View.java:813)
  at android.view.View$PerformClick.run(View.java:27640)
  at android.os.Handler.handleCallback(Handler.java:883)
  at android.os.Handler.dispatchMessage(Handler.java:100)
  at android.os.Looper.loop(Looper.java:230)
  at android.app.ActivityThread.main(ActivityThread.java:7725)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:526)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1034)
  ........省略N.....   
  "WQW TEST" prio=5 tid=3 TimeWating
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x12c44230 self=0x772f0ec000
  | sysTid=22938 nice=0 cgrp=default sched=0/0 handle=0x77391fbd50
  | state=S schedstat=( 274896 0 1 ) utm=0 stm=0 core=1 HZ=100
  | stack=0x77390f9000-0x77390fb000 stackSize=1039KB
  | held mutexes=
  at java.lang.Thread.sleep(Native method)
  - sleeping on <0x043831a6> (a java.lang.Object)
  at java.lang.Thread.sleep(Thread.java:440)
  - locked <0x043831a6> (a java.lang.Object)
  at java.lang.Thread.sleep(Thread.java:356)
  at com.example.test.MainActivity$onCreate$2$thread$1.run(MainActivity.kt:22)
  - locked <0x01aed1da> (a java.lang.Object)————————————————————关键行!!!
  at java.lang.Thread.run(Thread.java:919)
  • 1
  • 2
  • 3
  • 4
  • 5
  • 6
  • 7
  • 8
  • 9
  • 10
  • 11
  • 12
  • 13
  • 14
  • 15
  • 16
  • 17
  • 18
  • 19
  • 20
  • 21
  • 22
  • 23
  • 24
  • 25
  • 26
  • 27
  • 28
  • 29
  • 30
  • 31
  • 32
  • 33
  • 34

这是一个典型的主线程被锁阻塞的例子;

其中等待的锁是<0x01aed1da>,这个锁的持有者是线程 3。进一步搜索 “tid=3” 找到线程3, 发现它正在TimeWating。

那么ANR的原因找到了:线程3持有了一把锁,并且自身长时间不释放,主线程等待这把锁发生超时。

4.CPU被抢占

CPU usage from 0ms to 10625ms later (2020-03-09 14:38:31.633 to 2020-03-09 14:38:42.257):
  543% 2045/com.alibaba.android.rimet: 54% user + 89% kernel / faults: 4608 minor 1 major ————关键行!!!
  99% 674/android.hardware.camera.provider@2.4-service: 81% user + 18% kernel / faults: 403 minor
  24% 32589/com.wang.test: 22% user + 1.4% kernel / faults: 7432 minor 1 major
  ........省略N行.....
  • 1
  • 2
  • 3
  • 4
  • 5

如上日志,第二行是钉钉的进程,占据CPU高达543%,抢占了大部分CPU资源,因而导致发生ANR。

5.内存紧张导致ANR

如果有一份日志,CPU和堆栈都很正常(不贴出来了),仍旧发生ANR,考虑是内存紧张。

从CPU第一行信息可以发现,ANR的时间点是2022-10-31 22:38:58.468—CPU usage from 0ms to 21752ms later (2022-10-31 22:38:58.468 to 2020-10-31 22:39:20.220)

接着去系统日志里搜索am_meminfo, 这个没有搜索到。再次搜索onTrimMemory,果然发现了很多条记录;

10-31 22:37:19.749 20733 20733 E Runtime : onTrimMemory level:80,pid:com.xxx.xxx:Launcher0
10-31 22:37:33.458 20733 20733 E Runtime : onTrimMemory level:80,pid:com.xxx.xxx:Launcher0
10-31 22:38:00.153 20733 20733 E Runtime : onTrimMemory level:80,pid:com.xxx.xxx:Launcher0
10-31 22:38:58.731 20733 20733 E Runtime : onTrimMemory level:80,pid:com.xxx.xxx:Launcher0
10-31 22:39:02.816 20733 20733 E Runtime : onTrimMemory level:80,pid:com.xxx.xxx:Launcher0
  • 1
  • 2
  • 3
  • 4
  • 5

可以看出,在发生ANR的时间点前后,内存都处于紧张状态,level等级是80,查看Android API 文档;

``/** * Level for {@link #onTrimMemory(int)}: the process is nearing the end * of the background LRU list, and if more memory isn’t found soon it will * be killed. */ static final int TRIM_MEMORY_COMPLETE = 80;

可知80这个等级是很严重的,应用马上就要被杀死,被杀死的这个应用从名字可以看出来是桌面,连桌面都快要被杀死,那普通应用能好到哪里去呢?

一般来说,发生内存紧张,会导致多个应用发生ANR,所以在日志中如果发现有多个应用一起ANR了,可以初步判定,此ANR与你的应用无关。

6.系统服务超时导致ANR

系统服务超时一般会包含BinderProxy.transactNative关键字,请看如下日志:

"main" prio=5 tid=1 Native
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x727851e8 self=0x78d7060e00
  | sysTid=4894 nice=0 cgrp=default sched=0/0 handle=0x795cc1e9a8
  | state=S schedstat=( 8292806752 1621087524 7167 ) utm=707 stm=122 core=5 HZ=100
  | stack=0x7febb64000-0x7febb66000 stackSize=8MB
  | held mutexes=
  kernel: __switch_to+0x90/0xc4
  kernel: binder_thread_read+0xbd8/0x144c
  kernel: binder_ioctl_write_read.constprop.58+0x20c/0x348
  kernel: binder_ioctl+0x5d4/0x88c
  kernel: do_vfs_ioctl+0xb8/0xb1c
  kernel: SyS_ioctl+0x84/0x98
  kernel: cpu_switch_to+0x34c/0x22c0
  native: #00 pc 000000000007a2ac  /system/lib64/libc.so (__ioctl+4)
  native: #01 pc 00000000000276ec  /system/lib64/libc.so (ioctl+132)
  native: #02 pc 00000000000557d4  /system/lib64/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+252)
  native: #03 pc 0000000000056494  /system/lib64/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+60)
  native: #04 pc 00000000000562d0  /system/lib64/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+216)
  native: #05 pc 000000000004ce1c  /system/lib64/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+72)
  native: #06 pc 00000000001281c8  /system/lib64/libandroid_runtime.so (???)
  native: #07 pc 0000000000947ed4  /system/framework/arm64/boot-framework.oat (Java_android_os_BinderProxy_transactNative__ILandroid_os_Parcel_2Landroid_os_Parcel_2I+196)
  at android.os.BinderProxy.transactNative(Native method) ————————————————关键行!!!
  at android.os.BinderProxy.transact(Binder.java:804)
  at android.net.IConnectivityManager$Stub$Proxy.getActiveNetworkInfo(IConnectivityManager.java:1204)—关键行!
  at android.net.ConnectivityManager.getActiveNetworkInfo(ConnectivityManager.java:800)
  at com.xiaomi.NetworkUtils.getNetworkInfo(NetworkUtils.java:2)
  at com.xiaomi.frameworkbase.utils.NetworkUtils.getNetWorkType(NetworkUtils.java:1)
  at com.xiaomi.frameworkbase.utils.NetworkUtils.isWifiConnected(NetworkUtils.java:1)
  • 1
  • 2
  • 3
  • 4
  • 5
  • 6
  • 7
  • 8
  • 9
  • 10
  • 11
  • 12
  • 13
  • 14
  • 15
  • 16
  • 17
  • 18
  • 19
  • 20
  • 21
  • 22
  • 23
  • 24
  • 25
  • 26
  • 27
  • 28

从堆栈可以看出获取网络信息发生了ANR:getActiveNetworkInfo。

前文有讲过:系统的服务都是Binder机制(16个线程),服务能力也是有限的,有可能系统服务长时间不响应导致ANR。如果其他应用占用了所有Binder线程,那么当前应用只能等待。

可进一步搜索:blockUntilThreadAvailable关键字:

at android.os.Binder.blockUntilThreadAvailable(Native method)

如果有发现某个线程的堆栈,包含此字样,可进一步看其堆栈,确定是调用了什么系统服务。此类ANR也是属于系统环境的问题,如果某类型机器上频繁发生此问题,应用层可以考虑规避策略。

7.Suspended

"main" prio=5 tid=1 Suspended
  | group="main" sCount=1 dsCount=0 cgrp=bg_non_interactive handle=0x7fa2a39000
  | sysTid=16770 nice=-4 sched=0/0 cgrp=bg_non_interactive handle=0x7fa2a39000
  | state=S schedstat=( 2661049558440 288674775480 3568435 ) utm=226454 stm=39650 core=1 HZ=100
  | heldMutexes=
 at android.os.MessageQueue.removeMessages(MessageQueue.java:702)
 at android.os.Handler.removeCallbacks(Handler.java:487)
 at me.ele.android.lmagex.b$3.println(SourceFile:103)
 at android.os.Looper.loop(Looper.java:153)
 at android.app.ActivityThread.main(ActivityThread.java:5665)
 at java.lang.reflect.Method.invoke!(Native Method)
 at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:822)
 at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:712)
  • 1
  • 2
  • 3
  • 4
  • 5
  • 6
  • 7
  • 8
  • 9
  • 10
  • 11
  • 12
  • 13
  • app压后台时,线程优先级由-10降低到nice=-4,通过Handler进行removeCallbacks,线程被挂起导致ANR

8.Waiting

"main" prio=5 tid=1 Waiting
  | group="main" sCount=0 dsCount=0 flags=0 obj=0x731a0ec8 self=0xb40000753e8b6c00
  | sysTid=28146 nice=-10 cgrp=default sched=0/0 handle=0x753fe804f8
  | state=? schedstat=( 0 0 0 ) utm=0 stm=0 core=0 HZ=100
  | stack=0x7fd0403000-0x7fd0405000 stackSize=8192KB
  | held mutexes=
  at java.lang.Object.wait(Native method)
  - waiting on <0x025d68dd> (a android.opengl.GLSurfaceView$GLThreadManager)
  at java.lang.Object.wait(Object.java:442)
  at java.lang.Object.wait(Object.java:568)
  at android.opengl.GLSurfaceView$GLThread.onPause(GLSurfaceView.java:1731)
  at android.opengl.GLSurfaceView.onPause(GLSurfaceView.java:579)
  at com.amap.api.mapcore.util.e.onPause(SourceFile:117)
  at com.amap.api.mapcore.util.e.onDetachedGLThread(SourceFile:73)
  at com.amap.api.mapcore.util.c.destroy(SourceFile:5750)
  at com.amap.api.mapcore.util.t.onDestroy(SourceFile:207)
  at com.amap.api.maps.MapView.onDestroy(SourceFile:165)
  • 1
  • 2
  • 3
  • 4
  • 5
  • 6
  • 7
  • 8
  • 9
  • 10
  • 11
  • 12
  • 13
  • 14
  • 15
  • 16
  • 17
  • 主线程等待超时导致ANR

9.低内存导致问题

多数的低内存ANR是由于内存泄漏Memory Leak对象在内存heap堆中中分配的空间,进程中某些对象已经没有使用价值了,但还是可以直接/间接的引用到GcRoot,导致无法回收,总结一句话就是:本该回收的对象不能被回收而停留在堆内存中,从而产生了内存泄漏。
在这里插入图片描述

在memory-log中可以看到在初始时,手机管家为477,389K,而后一致在增加,ANR发生时已经到达了1,921,836K,在之后升至2,061,172K。综上,该问题为手机管家内存泄漏导致,低内存产生ANR。

10. 高IO问题

当iowait很高时,此时如果再做操作文件等动作,就会大概率发生ANR如下问题发生时,kswapd0已经排进前三,iowait已经非常高了。

在这里插入图片描述

11.加载大数据问题

用应用打开存有大数据的Excel表格时,就会出现阻塞,此时用户感觉不适,从而点击触发Input dispatching timed out类型ANR

在这里插入图片描述

可以看到Wait queue length: 31,31已经很高了。

在这里插入图片描述

从main-log可以看到当时是微信的其他进程ANR,CPU负载正常,微信tools进程CPU占用不正常,可以关注这一点,根据event-log和main-log已经定位到了ANR发生的时间点和类型以及CPU的占用信息。

在这里插入图片描述

从上面信息可以看到,应是微信打开excel表格,锁在了自己的代码逻辑中导致产生ANR。

12.Binder资源耗尽

首先查看cpu负载的情况,可以看到时间段内都为0

在这里插入图片描述

进一步查看堆栈信息,可以根据标注的地方判断是卡在binder

在这里插入图片描述

从堆栈以及binder-info可以看是卡在binder,还是binder资源耗尽。binder logs中是有看到等待(pending transaction) binder资源的。

在这里插入图片描述

可以看到第11行的关键字pending transaction

在这里插入图片描述

应用16个binder资源用完,没有binder资源,但是16个都是native状态,并没有block。binder资源用完,无法修改处理。

干货:ANR日志分析全面解析

声明:本文内容由网友自发贡献,不代表【wpsshop博客】立场,版权归原作者所有,本站不承担相应法律责任。如您发现有侵权的内容,请联系我们。转载请注明出处:https://www.wpsshop.cn/w/菜鸟追梦旅行/article/detail/292565
推荐阅读
相关标签
  

闽ICP备14008679号