Android ANR & SWT

ANR(Application Not Responding，即应用程序无响应)。在Android中，当应用程序在规定时间内没有处理完毕相应的事件,系统就会报出ANR。

ANR类型

• InputDispatchingTimedOut：应用程序主线程在5s内没有完成用户的input事件
• ServiceTimeout：应用程序没有执行完成service的bind/create/start/destroy/unbind操作，前台服务20s超时，后台服务200s超时
• BroadcastTimeout：应用程序在规定时间内没有执行完成onReceive操作，前台广播10s超时，后台广播60s超时
• ContentProviderTimeout：应用程序在20s内没有执行完成ContentProvider相关操作

产生原因

• 系统原因：由于Kernel/Framework/Driver等存在问题，导致系统不稳定最终表现出ANR
• 应用原因：主线程死锁、阻塞或者性能低下，需避免将耗时操作放在主线程

如何理解

• Java进程中主线程主要做如下两件事：Activity已经View相关在该线程中被绘制，以及事件（类似点击事件）响应等，这些事情都跟UI相关，所以主线程又叫做UI线程；轮训Handler消息队列和消息处理。
• 因此主线程被阻塞，那么就会导致应用UI的绘制出现异常，也会导致事件无法即使响应，例如出现冻屏现象，点击事件没有任何反应
• 除了Activity的生命周期在主线程里面，其他三大组件的生命周期也是运行在主线程中，因此Service、Broadcast、ContentProvider做了耗时操作也会阻塞主线程进行UI绘制或者消息处理
• 在主线程被阻塞的情况下， 这样给用户造成一种很不好的体验，因此Android引入了ANR机制，规定主线程阻塞超过一定时间就会触发ANR无响应弹窗

 PS：一定要把ANR和JE区分开，ANR是XXX无响应，JE是XXX已停止

一、如何分析ANR？

ANR类的问题有些可以直接从日志中排查出原因，例如广播类ANR；有些可能因为系统不稳定（例如系统进程system server进程崩溃，CPU耗时，IO耗时，低内存等原因）导致很难定位。因此我们需要一套思路来分析定位ANR。

无论是MTK平台还是展锐平台，我们都需要如下关键信息的日志：

• Logcat

logcat属于android原生提供的抓取日志的方式。可以通过logcat来初步定位anr发声时间以及上下文系统或者各个进程状态。

MTK平台的AP日志中主要有main_log和sys_log，如果跟通信相关，还需要去查看radio_log。

展锐平台的AP日志中主要有android.log、android_main.log、android_system.log、android_radio.log。

• EventLog

envents也属于android原生提供的一种日志。通过这个日志可以很简洁的呈现出系统的事件处理流程，包括时间，状态，便于我们分析定位问题

MTK平台的AP日志中主要是events_log开头的文件；展锐平台AP日志中主要android_events.log。

【Android日志分析】EventLog_android event日志_xqliu2134的博客-CSDN博客

• MTK DB

MTK通过db的方式来记录系统发生的一切JE/NE/ANR相关的堆栈，如下图，但是需要通过mtk的专用工具才能解析。

• 展锐 Traces

展锐平台的AP日志中有专门traces文件夹，该文件夹存放了每一次ANR的堆栈调用，系统信息，文件格式为xx_xxx-xx_anr_xx_xx_xx。

1、分析流程

MTK和展锐官网都有详细说明如何分析ANR问题，但这里我更推荐展锐的分析思路。

• 展锐

• MTK 旧

• MTK 新

相比两种分析思路，大体流程类似，可以总结分为如下几个步骤：

• 确认ANR类型、时间、进程号
• 初步查看堆栈信息，分析主线程是否有明显的错误（定位是否应用原因）
• 如果主线程没有明显异常，在确认是否系统原因，重点关注CPU负债、内存信息、LMDK、IO是否阻塞、重要的系统进程（Zygote/system_server/ActivityManager等）有无明显异常
• 如果即没有定位应用自身原因，也没有定位到系统原因，那么需要结合上下文日志进行综合分析，如果还是没有什么头绪，这种情况可能是堆栈没有抓取出来，可能其他什么原因，建议可以给平台提case

2、确认ANR类型和相关信息

• MTK如何快速定位？

如果测试提供的日志有AEE目录，那么可以先检查db_history快速找到对应的db文件：

 使用MTK的GAT工具加载db文件并解析：

• 展锐如何快速定位？

直接从YLOG的AP日志中找到对应时间端的traces文件：

• 通过Logcat定位

如果DEBUG或者YLOG里面没有相关的ANR日志，那么只有从logcat中查看ActivityManager进程是否有相关ANR的打印（PS：YLOG通常在android_system.log），例如：

 还可以再envent_log日志中搜索am_anr类型的日志，例如：

E012594  06-14 13:54:40.652  1110  4566 I am_anr  : [0,1648,com.android.settings,684310085,Input dispatching timed out (105fb5 com.android.settings/com.android.settings.network.telephony.MobileNetworkActivity (server) is not responding. Waited 8007ms for MotionEvent)]

3、初步查看主线程堆栈信息

为什么要优先去定位主线程信息？

根据ANR产生原因来看，即应用主线程做了耗时操作，根据分类可以是广播接受者、内容提供者、服务（四大组件都运行在主线程）中做了耗时操作；

当然Acitcity也有可能存在耗时产生InputDispatchingTimedOut类型的ANR，例如activity没有即使显示出来（分析焦点），activity view没有及时响应触摸点击等事件，handler中消息处理超时 等。

1）、堆栈信息结构

MTK通过db文件中的__exp_main.txt文件来定位，展锐通过traces来定位。traces显示的有如下几部分：

• ANR基本信息：参考《确认ANR类型和相关信息》

• ANR发生前后系统（CPU和MEM）情况

• ANR发生进程Signal Catcher线程堆栈信息

Signal Catcher线程后文会详细介绍，这里只需要知道他是抓取Java虚拟机堆栈的线程

• ANR发生进程主线程堆栈信息

线程堆栈中，如下截图表明为主线程，关键特征：线程组为main，tid为1

•  ANR发生进程其他线程堆栈信息：主线程堆栈信息之后紧跟着其他子线程的堆栈信息，例如binder线程、守护线程等。通常我们会根据主线程的相关信息，选择性是否有必要去查看其他子线程的信息，例如主线程block到binder子线程中，或者与某个子线程存在死锁

#线程名: main（如有daemon则代表守护线程)
#线程名"main"：通常为主线程，这个跟group不一样，有些子线程的group也是main，但他们不是主线程
#线程名"Binder"：通常为binder子线程
#prio: 线程优先级
#tid: 线程内部id
#线程状态: NATIVE
#线程状态Native：表明该线程当前运行在native层，通常会有一些c/c++代码堆栈打印
#线程状态Blocked：表明该线程被阻塞，通常为java某个方法被卡住，或者等待某个锁的释放

"main" prio=5 tid=1 Native
  | group="main" sCount=1 ucsCount=0 flags=1 obj=0x735086e8 self=0xb4000071e8c707b0
  | sysTid=1329 nice=0 cgrp=default sched=1073741824/0 handle=0x732dad44f8 
  | state=S schedstat=( 136542970431 292470333243 553823 ) utm=8774 stm=4879 core=3 HZ=100
  | stack=0x7febede000-0x7febee0000 stackSize=8188KB
  | held mutexes=
#第1行group: 线程所属的线程组; sCount: 线程挂起次数; dsCount: 用于调试的线程挂起次数; obj: 当前线程关联的java线程对象; self: 当前线程地址
#第2行sysTid：线程真正意义上的tid; nice: 调度有优先级; cgrp: 进程所属的进程调度; sched: 调度策略; handle: 函数处理地址
#第3行state: 线程状态; schedstat: CPU调度时间统计, 见proc/[pid]/task/[tid]/schedstat
#第3行utm/stm: 用户态/内核态的CPU时间(单位是jiffies), 见proc/[pid]/task/[tid]/stat
#第3行core: 该线程的最后运行所在核; HZ: 时钟频率
#第4行stack：线程栈的地址区间; stackSize：栈的大小
#第5行mutex: 所持有mutex类型，有独占锁exclusive和共享锁shared两类

#schedstat含义说明：
#nice值越小则优先级越高。此处nice=0, 可见优先级还是比较高的;
#schedstat括号中的3个数字依次是Running、Runable、Switch，紧接着的是utm和stm
#Running时间：CPU运行的时间，单位ns
#Runable时间：RQ队列的等待时间，单位ns
#Switch次数：CPU调度切换次数
#utm: 该线程在用户态所执行的时间，单位是jiffies，jiffies定义为sysconf(_SC_CLK_TCK)，默认等于10ms
#stm: 该线程在内核态所执行的时间，单位是jiffies，默认等于10ms

• Waiting Channels：如下日志，看起来waiting channels也中systid为线程id，后面binder_thread_read为native堆栈信息

#waiting channels 进程1366
----- Waiting Channels: pid 1366 at 2023-06-15 20:20:17.119970977+0800 -----
Cmd line: com.android.phone
#1366进程当时处于binder_thread_read函数中
sysTid=1366      binder_thread_read
#1371进程当时处于do_sigtimedwait函数中
sysTid=1371      do_sigtimedwait
sysTid=1372      pipe_read
sysTid=1374      futex_wait_queue_me
sysTid=1375      futex_wait_queue_me
sysTid=1376      futex_wait_queue_me
sysTid=1377      futex_wait_queue_me
sysTid=1378      futex_wait_queue_me
sysTid=1379      binder_thread_read
sysTid=1380      binder_thread_read
sysTid=1381      do_epoll_wait
........

----- end 1366 -----

2）、常见主线程堆栈能够定位的案例

• Java/Native层发生阻塞

#SP属于IO操作，建议通过apply方式进行，将同步改成异步；或者使用子线程进行保存
"main" prio=5 tid=1 Native
  | group="" sCount=0 dsCount=0 flags=0 obj=0x7877b2c0 self=0x7e5f214c00
  | sysTid=25160 nice=0 cgrp=default sched=0/0 handle=0x7ee5d67548
  | state=? schedstat=( 0 0 0 ) utm=0 stm=0 core=0 HZ=100
  | stack=0x7fe88ba000-0x7fe88bc000 stackSize=8MB
  | held mutexes=
  at java.io.FileDescriptor.sync(Native method)
  at android.os.FileUtils.sync(FileUtils.java:197)
  at android.app.SharedPreferencesImpl.writeToFile(SharedPreferencesImpl.java:777)
  at android.app.SharedPreferencesImpl.access$900(SharedPreferencesImpl.java:54)
  at android.app.SharedPreferencesImpl$2.run(SharedPreferencesImpl.java:642)
  at android.app.SharedPreferencesImpl.enqueueDiskWrite(SharedPreferencesImpl.java:661)
  at android.app.SharedPreferencesImpl.access$100(SharedPreferencesImpl.java:54)
  at android.app.SharedPreferencesImpl$EditorImpl.commit(SharedPreferencesImpl.java:580)
  ...
  at android.os.Handler.handleCallback(Handler.java:873)
  at android.os.Handler.dispatchMessage(Handler.java:99)
  at android.os.Looper.loop(Looper.java:242)
  at android.app.ActivityThread.main(ActivityThread.java:7227)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:499)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:962)

• 主动睡眠Sleep

• 等待其他线程唤醒Waiting

• 被其他线程Block

• Binder通信出现异常

• 死锁阻塞

Subject: Input dispatching timed out (5aeac33 com.gallery20/com.gallery20.app.albumset.AlbumSetActivity (server) is not responding. Waited 12001ms for KeyEvent)

----- pid 28645 at 2023-03-05 14:53:40.390288943+0800 ----- 
Cmd line: com.gallery20

"main" prio=5 tid=1 Blocked
  | group="main" sCount=1 ucsCount=0 flags=1 obj=0x72c91108 self=0xb400007490122f50
  | sysTid=28645 nice=0 cgrp=default sched=1073741824/0 handle=0x75d93c64f8
  | state=S schedstat=( 472247078 48874165 534 ) utm=34 stm=13 core=3 HZ=100
  | stack=0x7fdf6cd000-0x7fdf6cf000 stackSize=8188KB
  | held mutexes=
  kernel: __switch_to+0x134/0x150
  kernel: futex_wait_queue_me+0x134/0x1b4
  kernel: futex_wait+0x11c/0x2cc
  kernel: do_futex+0x10c/0x18e8
  kernel: __arm64_sys_futex+0x14c/0x1cc
  kernel: el0_svc_common+0x98/0x160
  kernel: el0_svc_handler+0x60/0x78
  kernel: el0_svc+0x8/0x300
  at com.transsion.gallery.data.z1.F(unavailable:0)
  - waiting to lock <0x00e20977> (a com.transsion.gallery.data.z1) held by thread 38 ------------------------->等待线程38释放持锁0x00e20977
  at com.gallery20.app.albumset.loader.AlbumSetLoader.forceLoad(AlbumSetLoader.kt:2)
  at androidx.loader.content.Loader.onContentChanged(Loader.java:2)
  at com.gallery20.app.albumset.loader.AlbumSetLoader.j(AlbumSetLoader.kt:1)
  at com.gallery20.app.albumset.loader.AlbumSetLoader.g(unavailable:0)
  at com.gallery20.app.albumset.loader.a.a(unavailable:2)
  at com.transsion.gallery.data.b1.B(MediaSet.java:2)
  at com.transsion.gallery.data.t.c(ChangeNotifier.java:2)
  at com.transsion.gallery.data.d0$a.f(DataManager.java:3)
  - locked <0x082a79e4> (a com.transsion.gallery.data.d0$a) ------------------------->持锁0x082a79e4 线程37等待该锁释放

"ModernAsyncTask #1" prio=5 tid=38 Blocked
  | group="main" sCount=1 ucsCount=0 flags=1 obj=0x12c81e08 self=0xb4000074901844d0
  | sysTid=29361 nice=10 cgrp=default sched=0/0 handle=0x728da61cb0
  | state=S schedstat=( 3076999 42343614 20 ) utm=0 stm=0 core=4 HZ=100
  | stack=0x728d95e000-0x728d960000 stackSize=1039KB
  | held mutexes=
  kernel: __switch_to+0x134/0x150
  kernel: futex_wait_queue_me+0x134/0x1b4
  kernel: futex_wait+0x11c/0x2cc
  kernel: do_futex+0x10c/0x18e8
  kernel: __arm64_sys_futex+0x14c/0x1cc
  kernel: el0_svc_common+0x98/0x160
  kernel: el0_svc_handler+0x60/0x78
  kernel: el0_svc+0x8/0x300
  at com.transsion.gallery.data.b1.l(MediaSet.java:1)
  - waiting to lock <0x053ab06f> (a java.lang.Object) held by thread 37 ------------------------->等待线程37释放持锁0x053ab06f
  at com.transsion.gallery.data.z1$b.b(VirtualMyAlbumSet.kt:28)
  at com.transsion.gallery.data.z1.F(VirtualMyAlbumSet.kt:3)
  - locked <0x00e20977> (a com.transsion.gallery.data.z1)    ------------------------->持锁0x00e20977 主线程等待这把锁释放

"thread-pool-0" prio=5 tid=37 Blocked
  | group="main" sCount=1 ucsCount=0 flags=1 obj=0x12c81a18 self=0xb400007490172eb0
  | sysTid=29360 nice=10 cgrp=default sched=0/0 handle=0x728db6bcb0
  | state=S schedstat=( 27161539 66263229 62 ) utm=1 stm=1 core=1 HZ=100
  | stack=0x728da68000-0x728da6a000 stackSize=1039KB
  | held mutexes=
  kernel: __switch_to+0x134/0x150
  kernel: futex_wait_queue_me+0x134/0x1b4
  kernel: futex_wait+0x11c/0x2cc
  kernel: do_futex+0x10c/0x18e8
  kernel: __arm64_sys_futex+0x14c/0x1cc
  kernel: el0_svc_common+0x98/0x160
  kernel: el0_svc_handler+0x60/0x78
  kernel: el0_svc+0x8/0x300
  at com.transsion.gallery.data.d0$a.g(unavailable:0)
  - waiting to lock <0x082a79e4> (a com.transsion.gallery.data.d0$a) held by thread 1  ------------------------->等待主线程1释放持锁0x082a79e4
  at com.transsion.gallery.data.d0.s(DataManager.java:5)
  - locked <0x0ecc274e> (a com.transsion.gallery.data.d0)
  at com.transsion.gallery.data.t.<init>(ChangeNotifier.java:4)
  at com.transsion.gallery.data.n0$a.<init>(LocalAlbum.java:1)
  at com.transsion.gallery.data.n0.<init>(LocalAlbum.java:18)
  at com.transsion.gallery.data.b1.l(MediaSet.java:9)
  - locked <0x053ab06f> (a java.lang.Object)
  at com.transsion.gallery.data.b1.l(MediaSet.java:7)
  - locked <0x053ab06f> (a java.lang.Object)     ------------------------->持锁0x053ab06f 线程38等待这把锁释放

4、确定系统当前状态

实际情况，很多时候遇到的主线程堆栈信息并不能真正定位到ANR发生的原因，主线程的堆栈信息也只能作为一个参考，因为堆栈并不能记录线程处于这个状态的时间。此时要结合系统等各种信息才能精确定位。

1）、CPU负荷

出现上述信息，可以怀疑是CPU bound，通常CPU usage超过90%就可以认为CPU比较繁忙，需要性能同事解决CPU占用率太高的问题。具体分析流程如下几步：

• 确认是否存在CPU high loading
•  排除系统是否存在限频策略，常见的有温度超过一定阀值对CPU进行降频，还有管理功耗和性能分配的PPM机制
• 抓取火焰图确定具体线程抢占了CPU

CPU占用率可以参考MTK官方相关教程：

MediaTek On-Line | Loginhttps://online.mediatek.com/QuickStart/QS00152#QSS01631MediaTek On-Line | Loginhttps://online.mediatek.com/QuickStart/QS00164#QSS01723

2）、是否低内存/内存泄漏

出现上述信息，可以怀疑是memory bound，内存不足通常会触发lowmemorykiller机制，他会根据进程的adj优先级去干掉低优先级的进程（adj越大优先级越低，如果已经开始kill adj小于100的进程，那么说明内存非常不足）。

之前的android版本放在kernel层，该进程名称叫做kswapd（如果kswapd进程在cpu info信息中排名前三，说明kswapd进程非常活跃，lowmemorykiller机制已经被触发），最新的android版本讲部分机制移动到framework，由system server启动。

Memory bound的关键特征主要如上截图三类：查看CPU INFO中的kswap进程；在android日志搜索lowmemorykiller；在kernel日志中搜索lowmemorykiller，例如：

3)、IO Check

出现上述信息，可以怀疑是EMMC IO bound，请贵司performance owner先解决IO Loading过高问题。同时，对于SWT/SWT owner来讲，我们能做的就是：排查是否存在IO loading高，以及找出具体process信息。

对于IO bound，通常考虑进行文件操作的时候出现，系统上层更多的关注如下日志：

AnrManager: 97% TOTAL: 47% user + 42% kernel + 8.1% iowait + 0% softirq

        -----> 97% total 表示系统整体负荷，如果超过90%可以认为整体负荷偏高。他的计算逻辑是前面所有进程使用率相加/8（当前大部分手机都是8核）

        -----> 47% user 表示用户空间CPU占比，通常超过50%就可以认为用户空间进程CPU负荷较高，当然这块并不代表整体负荷，但是他和kernel的对比可以看出来当前是那个模块比较卡

        -----> 42% kernel 表示内核空间CPU占比，

        ------> 8.1% iowait 表示当前IO比较繁忙，通常超过10%就可以认为IO阻塞

4）、系统负荷的一些总计

ANR发生前后的系统CPU负荷情况汇总如下：

06-16 16:16:28.590  1853  2073 E ActivityManager: Load: 16.25 / 29.48 / 38.33 

这行得知Cpu的负载，在Linux操作系统上，输入uptime也能得到一段时间的负载。

uptime 20:09:54 up 71 days, 10:48, 1 user, load average: 0.99, 0.78, 0.86

那么负载是什么意思呢？Load后面的三个数字的意思分别是1分钟、5分钟、15分钟内系统的平均负荷。当CPU完全空闲的时候，平均负荷为0；当CPU工作量饱和的时候，平均负荷为1，通过Load可以判断系统负荷是否过重。有一个形象的比喻：个CPU想象成一座大桥，桥上只有一根车道，所有车辆都必须从这根车道上通过，系统负荷为0，意味着大桥上一辆车也没有，系统负荷为0.5，意味着大桥一半的路段有车，系统负荷为1.0，意味着大桥的所有路段都有车，也就是说大桥已经"满"了，系统负荷为2.0，意味着车辆太多了，大桥已经被占满了（100%），后面等着上桥的车辆还有一倍。大桥的通行能力，就是CPU的最大工作量；桥梁上的车辆，就是一个个等待CPU处理的进程（process）。

经验法则是这样的：
当系统负荷持续大于0.7，你必须开始调查了，问题出在哪里，防止情况恶化。
当系统负荷持续大于1.0，你必须动手寻找解决办法，把这个值降下来。
当系统负荷达到5.0，就表明你的系统有很严重的问题

如果只有1分钟的系统负荷大于1.0，其他两个时间段都小于1.0，这表明只是暂时现象，问题不大。
如果15分钟内，平均系统负荷大于1.0（调整CPU核心数之后），表明问题持续存在，不是暂时现象。所以，你应该主要观察"15分钟系统负荷"，将它作为电脑正常运行的指标。

而我们现在的手机是多核CPU架构，八核的多的是，意味着Cpu处理的能力就乘以了８，每个核运行的时间可以从下面的文件中得到，/sys/devices/system/cpu/cpu%d/cpufreq/stats/time_in_state 中读取的，%d代表是CPU的核。文件中记录了 CPU 从开机到读取文件时，在各个频率下的运行时间，单位：10 mS。

上面说了一堆，其实有点云里雾里的，其实这里的参考意义并不是很大，可以给出如下几个场景：

AnrManager: Load: 0.0 / 0.0 / 0.0               ---->负载没有dump出来

AnrManager: Load: 19.52 / 18.62 / 18.59   ---->负载一般般

AnrManager: Load: 47.07 / 35.93 / 26.63  ----->负载比较高

使用adb shell cat /sys/devices/system/cpu/cpu1/cpufreq/stats/time_in_state查看 频度

使用adb shell cat /sys/devices/system/cpu/cpu1/cpufreq/stats/time_in_state查看
频度       时间
652800 1813593
1036800 46484
1401600 521974
1689600 2956667
1843200 83065
1958400 53516
2016000 251693

ANR发生前后的系统各个进程负荷情况汇总如下：

• kswapd0 cpu占用率偏高，系统整体运行会缓慢，从而引起各种ANR。把问题转给"内存优化"，请他们进行优化。
• logd CPU占用率偏高，也会引起系统卡顿和ANR，因为各个进程输出LOG的操作被阻塞从而执行的极为缓慢。
• Vold占用CPU过高，会引起系统卡顿和ANR，请负责存储的同学先调查
• qcom.sensor CPU占用率过高，会引起卡顿，请系统同学调查
• 应用自身CPU占用率较高，高概率应用自身问题
• 系统CPU占用率不高，但主线程在等待一个锁，高概率应用自身问题
• 应用处于D状态，发生ANR，如果最后的操作是refriger，那么是应用被冻结了，正常情况下是功耗优化引起的。

5）、系统高负载案例

如下摘抄的一份系统高负荷引起的ANR日志分析记录

events_log_2023_0321_110202.curf中日志显示03-21 11:06:09发生anr，有motionevent超过8s未处理                                                                                                                    
03-21 11:06:09.700765  1329 22520 I am_anr  : [18,14904,com.android.settings,952745541,Input dispatching timed out (d6e706e com.android.settings/com.android.settings.SubSettings (server) is not responding. Waited 8026ms for MotionEvent)]

sys_log_2023_0321_110202.curf：

03-21 11:06:25.019610  1329 22520 I AnrManager: ANR in com.android.settings (com.android.settings/.SubSettings), time=70564711
03-21 11:06:25.019610  1329 22520 I AnrManager: Reason: Input dispatching timed out (d6e706e com.android.settings/com.android.settings.SubSettings (server) is not responding. Waited 8026ms for MotionEvent)
03-21 11:06:25.019610  1329 22520 I AnrManager: Load: 47.07 / 35.93 / 26.63
03-21 11:06:25.019610  1329 22520 I AnrManager: ----- Output from /proc/pressure/memory -----
03-21 11:06:25.019610  1329 22520 I AnrManager: some avg10=30.80 avg60=30.12 avg300=18.88 total=953043802位是jiffies，默认等于10ms
03-21 11:06:25.019610  1329 22520 I AnrManager: full avg10=11.77 avg60=8.49 avg300=4.92 total=388612825
03-21 11:06:25.019610  1329 22520 I AnrManager: ----- End output from /proc/pressure/memory -----
03-21 11:06:25.019610  1329 22520 I AnrManager: 
03-21 11:06:25.019610  1329 22520 I AnrManager: Android time :[2023-03-21 11:06:24.93] [70579.969]
03-21 11:06:25.019610  1329 22520 I AnrManager: CPU usage from 36086ms to 0ms ago (2023-03-21 11:05:33.589 to 2023-03-21 11:06:09.675):
03-21 11:06:25.019610  1329 22520 I AnrManager:   137% 1329/system_server: 90% user + 47% kernel / faults: 163690 minor 993 major
03-21 11:06:25.019610  1329 22520 I AnrManager:   66% 158/kswapd0: 0% user + 66% kernel
03-21 11:06:25.019610  1329 22520 I AnrManager:   30% 4249/com.android.vending: 19% user + 10% kernel / faults: 35458 minor 91 major
...
03-21 11:06:25.019789  1329 22520 I AnrManager: 97% TOTAL: 47% user + 42% kernel + 8.1% iowait + 0% softirq

anrmanager统计的系统负载信息显示从2023-03-21 11:05:33.589到2023-03-21 11:06:09.675，
36秒内系统负载较高，整体cpu使用率达到97%，内存压力较大，kswpad的cpu占用率达到66%，谷歌应用市场也有30%的cpu占用，iowait 8.1%

main_log_2023_0321_110202.curf，中显示系统内存压力突破low water mark，swap可用小于设定阈值，271440kB < 310100kB，后面内存压力继续升级进入critical状态(device is not respondin),系统进行查杀后依旧低内存
03-21 11:06:05.206966   476   476 I lowmemorykiller: Kill 'com.android.remoteprovisioner' (22326), uid 1810159, oom_score_adj 905 to free 62608kB rss, 50716kB swap; reason: low watermark is breached and swap is low (271440kB < 310100kB)
03-21 11:06:07.159082   476   476 I lowmemorykiller: Kill 'com.android.vending' (21874), uid 10129, oom_score_adj 200 to free 118056kB rss, 57132kB swap; reason: device is not responding
03-21 11:06:07.365190   476   476 I lowmemorykiller: Kill 'android.process.media' (22074), uid 10040, oom_score_adj 915 to free 62288kB rss, 51384kB swap; reason: low watermark is breached and swap is low (229884kB < 310100kB)
03-21 11:06:07.809472   476   476 I lowmemorykiller: Kill 'com.android.vending:background' (21640), uid 10129, oom_score_adj 905 to free 95092kB rss, 55544kB swap; reason: low watermark is breached and swap is low (225344kB < 310100kB)
03-21 11:06:08.237618   476   476 I lowmemorykiller: Kill 'com.android.systemui' (22254), uid 1810090, oom_score_adj 500 to free 112924kB rss, 47164kB swap; reason: device is not responding
03-21 11:06:09.317850   476   476 I lowmemorykiller: Kill 'com.google.android.inputmethod.latin' (20211), uid 1810151, oom_score_adj 200 to free 83364kB rss, 47800kB swap; reason: device is not responding

系统统计从 2023-03-21 11:06:10.043 到2023-03-21 11:06:10.485，450ms内系统负载信息
system_server有binder线程cpu占用比较高，谷歌应用市场cpu占用也比较高(内存回收线程HeapTaskDaemon27%，其它几个线程看起来是有应用正在安装)，
kswapd还处于活跃状态36%的cpu占用,iowait 20%
03-21 11:06:25.019789  1329 22520 I AnrManager: CPU usage from 368ms to 810ms later (2023-03-21 11:06:10.043 to 2023-03-21 11:06:10.485):
03-21 11:06:25.019817  1329 22520 I AnrManager:   107% 1329/system_server: 44% user + 62% kernel / faults: 1946 minor 20 major
03-21 11:06:25.019817  1329 22520 I AnrManager:     38% 22520/AnrConsumer: 11% user + 26% kernel
03-21 11:06:25.019817  1329 22520 I AnrManager:     35% 3309/binder:1329_3: 17% user + 17% kernel
03-21 11:06:25.019817  1329 22520 I AnrManager:     11% 1361/android.bg: 5.9% user + 5.9% kernel
03-21 11:06:25.019817  1329 22520 I AnrManager:     5.9% 4740/binder:1329_16: 2.9% user + 2.9% kernel
03-21 11:06:25.019817  1329 22520 I AnrManager:     2.9% 1368/ActivityManager: 0% user + 2.9% kernel
03-21 11:06:25.019817  1329 22520 I AnrManager:     2.9% 2902/jobscheduler.bg: 2.9% user + 0% kernel
03-21 11:06:25.019817  1329 22520 I AnrManager:     2.9% 4552/binder:1329_E: 2.9% user + 0% kernel
03-21 11:06:25.019817  1329 22520 I AnrManager:     2.9% 30846/pool-3560-threa: 0% user + 2.9% kernel
03-21 11:06:25.019817  1329 22520 I AnrManager:   86% 4249/com.android.vending: 68% user + 18% kernel / faults: 452 minor 2 major
03-21 11:06:25.019817  1329 22520 I AnrManager:     27% 4260/HeapTaskDaemon: 24% user + 3.1% kernel
03-21 11:06:25.019817  1329 22520 I AnrManager:     15% 22019/VerifierDataSto: 9.3% user + 6.2% kernel
03-21 11:06:25.019817  1329 22520 I AnrManager:     12% 22010/VerifierDataSto: 9.3% user + 3.1% kernel
03-21 11:06:25.019817  1329 22520 I AnrManager:     12% 22013/VerifierDataSto: 6.2% user + 6.2% kernel
03-21 11:06:25.019817  1329 22520 I AnrManager:     12% 22018/VerifierDataSto: 6.2% user + 6.2% kernel
03-21 11:06:25.019817  1329 22520 I AnrManager:     6.2% 4411/bgExecutor #2: 3.1% user + 3.1% kernel
03-21 11:06:25.019817  1329 22520 I AnrManager:     6.2% 17663/-verify_apps.db: 3.1% user + 3.1% kernel
03-21 11:06:25.019817  1329 22520 I AnrManager:   36% 158/kswapd0: 0% user + 36% kernel

...
03-21 11:06:25.019830  1329 22520 I AnrManager: 93% TOTAL: 32% user + 40% kernel + 20% iowait + 0.2% softirq

bugreport中FS/data/anr/anr_2023-03-21-11-06-10-574信息显示setting主线程在加载资源：
"main" prio=5 tid=1 Native
  | group="main" sCount=1 ucsCount=0 flags=1 obj=0x735086e8 self=0xb4000071e8c707b0
  | sysTid=14904 nice=-10 cgrp=default sched=1073741824/0 handle=0x732dad44f8
  | state=S schedstat=( 3732790209 1396815178 11456 ) utm=221 stm=152 core=6 HZ=100
  | stack=0x7febede000-0x7febee0000 stackSize=8188KB
  | held mutexes=
  native: #00 pc 000000000004f66c  /apex/com.android.runtime/lib64/bionic/libc.so (syscall+28) (BuildId: 30a4e47a740c4b6340eb774cc965a471)
  native: #01 pc 000000000047a830  /apex/com.android.art/lib64/libart.so (art::ConditionVariable::WaitHoldingLocks(art::Thread*)+140) (BuildId: 28c5aa8a2e8fc5df069f717d6e94f7fe)
  native: #02 pc 00000000005b54b4  /apex/com.android.art/lib64/libart.so (art::JNI<false>::NewStringUTF(_JNIEnv*, char const*)+5264) (BuildId: 28c5aa8a2e8fc5df069f717d6e94f7fe)
  native: #03 pc 00000000000c26c0  /system/lib64/libandroid_runtime.so (android::android_content_StringBlock_nativeGetString(_JNIEnv*, _jobject*, long, int)+320) (BuildId: 05fe8a9176f207a5b72cad02be981372)
  at android.content.res.StringBlock.nativeGetString(Native method)
  at android.content.res.StringBlock.getSequence(StringBlock.java:124)
  - locked <0x0bd693b0> (a android.content.res.StringBlock)
  at android.content.res.ApkAssets.getStringFromPool(ApkAssets.java:351)
  - locked <0x057cb229> (a android.content.res.ApkAssets)
  at android.content.res.AssetManager.getPooledStringForCookie(AssetManager.java:875)
  at android.content.res.AssetManager.getResourceValue(AssetManager.java:570)
  - locked <0x091689ae> (a android.content.res.AssetManager)
  at android.content.res.AssetManager.getResourceText(AssetManager.java:589)
  - locked <0x091689ae> (a android.content.res.AssetManager)
  at android.content.res.Resources.getText(Resources.java:448)
  at android.app.ApplicationPackageManager.getText(ApplicationPackageManager.java:2350)

wait channel显示主线程正在缺页中断逻辑中，与前面内存紧张信息一致
----- Waiting Channels: pid 14904 at 2023-03-21 11:06:10.585294619+0800 -----
Cmd line: com.android.settings

sysTid=14904     filemap_fault

system_server的GC信息：

Total mutator paused time: 3.144s
Total time waiting for GC to complete: 16.278s
Total GC count: 1092
Total GC time: 405.638s
Total blocking GC count: 131
Total blocking GC time: 76.465s
也显示系统GC block的次数131次，时间76s

6）、系统低负载案例（区别高负载）

04-25 08:56:04.566836  1543  5578 I AnrManager: ANR in com.android.systemui, time=464344261
04-25 08:56:04.566836  1543  5578 I AnrManager: Reason: Input dispatching timed out (39d2ded NavigationBar0 (server) is not responding. Waited 5000ms for MotionEvent)
04-25 08:56:04.566836  1543  5578 I AnrManager: Load: 21.05 / 16.18 / 15.22
04-25 08:56:04.566836  1543  5578 I AnrManager: ----- Output from /proc/pressure/memory -----
04-25 08:56:04.566836  1543  5578 I AnrManager: some avg10=17.68 avg60=4.18 avg300=1.31 total=4461853313
04-25 08:56:04.566836  1543  5578 I AnrManager: full avg10=3.34 avg60=0.76 avg300=0.31 total=2391788218
04-25 08:56:04.566836  1543  5578 I AnrManager: ----- End output from /proc/pressure/memory -----
04-25 08:56:04.566836  1543  5578 I AnrManager: ----- Output from /proc/pressure/cpu -----
04-25 08:56:04.566836  1543  5578 I AnrManager: some avg10=51.58 avg60=13.60 avg300=5.69 total=32665412467
04-25 08:56:04.566836  1543  5578 I AnrManager: ----- End output from /proc/pressure/cpu -----
04-25 08:56:04.566836  1543  5578 I AnrManager: ----- Output from /proc/pressure/io -----
04-25 08:56:04.566836  1543  5578 I AnrManager: some avg10=4.10 avg60=0.95 avg300=0.31 total=1916960510
04-25 08:56:04.566836  1543  5578 I AnrManager: full avg10=0.00 avg60=0.01 avg300=0.00 total=1091754285

04-25 08:56:04.566836  1543  5578 I AnrManager: ----- End output from /proc/pressure/io 

如上Load才20左右，一般被定义为不是负载不是很高

04-25 08:56:04.566836  1543  5578 I AnrManager: Android time :[2024-04-25 08:56:04.40] [464352.875]
04-25 08:56:04.566836  1543  5578 I AnrManager: CPU usage from 34829ms to 4307ms ago (2024-04-25 08:55:20.958 to 2024-04-25 08:55:51.480):
04-25 08:56:04.566836  1543  5578 I AnrManager:   39% 1543/system_server: 25% user + 14% kernel / faults: 59301 minor 12495 major
04-25 08:56:04.566836  1543  5578 I AnrManager:   11% 143/kswapd0: 0% user + 11% kernel
04-25 08:56:04.566836  1543  5578 I AnrManager:   10% 17169/com.android.systemui: 6.8% user + 3.3% kernel / faults: 13881 minor 8998 major

04-25 08:56:04.567082  1543  5578 I AnrManager: 20% TOTAL: 8.9% user + 10% kernel + 0% iowait + 0.9% irq + 0.3% softirq

04-25 08:56:04.567082  1543  5578 I AnrManager: CPU usage from 141ms to 2263ms later (2024-04-25 08:55:55.928 to 2024-04-25 08:55:58.050):
04-25 08:56:04.567082  1543  5578 I AnrManager:   178% 1543/system_server: 87% user + 90% kernel / faults: 3449 minor 141 major / 04-25 08:56:04.567082  1543  5578 I AnrManager:     ------->  67% 5580/AnrAuxiliaryTas: 19% user + 47% kernel

04-25 08:56:04.567135  1543  5578 I AnrManager:   83% 143/kswapd0: 0% user + 83% kernel
04-25 08:56:04.567135  1543  5578 I AnrManager:   64% 25813/com.whatsapp: 50% user + 14% kernel / faults: 393 minor 1004 major

04-25 08:56:04.567419  1543  5578 I AnrManager: 95% TOTAL: 39% user + 50% kernel + 0.4% iowait + 2.9% irq + 1.6% softirq

如上打印，总共两次ANR统计，一般先看第一次高不高，在看第二次高不高，如果第一次不是不是很高，第二次很高的话通常为anr触发后系统systemserver进程进行anr dump的时候导致的高，此为正常现象

04-25 08:49:55.557291   460   460 I lowmemorykiller: Kill 'com.google.android.cellbroadcastreceiver' (2923), uid 10215, oom_score_adj 965 to free 57920kB rss, 35116kB swap; reason: device is not responding
04-25 08:56:04.405640   460   460 I lowmemorykiller: Kill 'com.transsion.hamal' (10747), uid 1000, oom_score_adj 985 to free 47080kB rss, 41272kB swap; reason: low watermark is breached and thrashing (32%)
04-25 08:56:05.487397   460   460 I lowmemorykiller: Kill 'filters.image.online_process' (2432), uid 10165, oom_score_adj 995 to free 60980kB rss, 65612kB swap; reason: low watermark is breached and thrashing (17%)
04-25 08:56:05.956605   460   460 I lowmemorykiller: Kill 'com.smartlife.nebula' (26853), uid 10262, oom_score_adj 995 to free 57292kB rss, 42836kB swap; reason: low watermark is breached and thrashing (8%)
04-25 08:56:06.247845   460   460 I lowmemorykiller: Kill 'com.transsion.iotservice:iotcard' (27317), uid 1000, oom_score_adj 995 to free 59692kB rss, 44572kB swap; reason: low watermark is breached and thrashing (4%)
04-25 08:56:06.450346   460   460 I lowmemorykiller: Kill 'com.transsion.mediapipefilters:segment' (2505), uid 10175, oom_score_adj 975 to free 55156kB rss, 47200kB swap; reason: low watermark is breached and thrashing (2%)
04-25 08:56:06.649919   460   460 I lowmemorykiller: Kill 'com.transsion.aod' (28287), uid 1000, oom_score_adj 985 to free 47536kB rss, 38360kB swap; reason: low watermark is breached and thrashing (1%)
04-25 08:56:06.803312   460   460 I lowmemorykiller: Kill 'com.twitter.android' (29350), uid 10285, oom_score_adj 975 to free 73572kB rss, 70624kB swap; reason: low watermark is breached and thrashing (1%)
04-25 08:56:07.002549   460   460 I lowmemorykiller: Kill 'com.android.rkpdapp' (4947), uid 10221, oom_score_adj 975 to free 54044kB rss, 39088kB swap; reason: low watermark is breached and thrashing (1%)
04-25 08:56:07.176609   460   460 I lowmemorykiller: Kill 'com.android.settings' (4899), uid 1000, oom_score_adj 975 to free 51012kB rss, 39700kB swap; reason: low watermark is breached and thrashing (2%)

如上lwk进行内存查杀，查杀的进程的adj都是在900以上，其实900以上的进程优先级并不是很高，表明属于正常的空闲进程查杀，进一步说明系统负载并不是很高。通常认为adj被查杀到杀到200，100，0的时候系统内存压力就有点大了。

二、常用Android相关机制

1、Signal Catcher线程

Signal Catcher线程在每个Java进程中都会存在。正常运行时，它将挂起等待信号3(以及信号10)的到来。当该进程接收到信号3时，将会交由Signal Catcher线程处理，处理的函数HandleSigQuit。即Signal Catcher线程是Android虚拟机用来抓取每个进程的堆栈信息，这个过程我们称作为在做DumpStack，当然其他线程可以会停在art::ConditionVariable::WaitHoldingLocks。

基本上每份traces日志中都有如下相关信息，这属于正常的堆栈：

更多Signal Catcher线程相关知识可以参考《Android Runtime | Trace文件的生成机制》

2、App is idle

在MTK的流程中，其中有个环节是去检查app是否空闲，当APP空闲的时候，主线程堆栈通常如下， 即MessageQueue停留在nativePollOnce，表示主线程没有需要处理的消息；当然也可能此状态是没有dump出状态，或者ANR已经发生，没有dump出ANR的堆栈

3、Binder通信

很多ANR问题发生在Binder通信过程中，例如某主线程在等待对端的binder数据，这里记录一下，我遇到的几种binder相关堆栈：

1）、Binder客户端：等待获取binder对端服务的数据

如下日志，典型的等待对端数据，客户端进程的binder线程在native层调用talkWithDriver去读取binder驱动的数据，然后通过transact方法回调到BpBinder，最终客户端进程才能获取到数据。

2）、Binder服务端

Idle表示当前binder服务端比较空闲，关键native日志为getAndExecuteCommand，在Binder框架库中，该函数为binder服务主线程轮训调用binder驱动接口获取是否有对端数据；

Busy表示当前binder服务端比较繁忙或者阻塞，关键navtive日志为executeCommand，在Binder框架库中，该函数为binder服务主线程已经轮训到客户端发过来的请求或者数据，并且已经开始执行，并且回调到具体服务实现子类中的transact函数中，即卡在该处，可能正在执行Service中某个具体ACTION。

3）、 只有artJniMethodEnd的打印

上面的堆栈有些不一样，native方法不清楚执行成功没有

{"transactNative",      "(ILandroid/os/Parcel;Landroid/os/Parcel;I)Z", (void*)android_os_BinderProxy_transact},

但是可以肯定的是，一个 JNI 函数做了很多的事情，在真正的 native 函数调用的前后分别有 JniMethodStart 和 JniMethodEnd 包住，具体的可以参考《从Java调用一个 Native 函数》

4)、Binder对端Check

4、LWDK机制

三、ANR经典案例

四、SWT

1、SWT概念和原理

System Server进程是Android的一个核心进程，里面为APP运行提供了核心的服务。如果System Server的一些核心服务和重要线程卡住，就会导致相应的功能异常。

如手机发生hang机，输入无响应，无法启动APP等一些不正常的情况。而且，如果没有一种机制，让这些服务复位的话，那么将严重影响客户体验。尤其是当前大多数手机把电池封装在手机里面的这种，想拨电池重启都很难。

所以有必要在核心服务和核心线程卡住的时候，让系统有自动复位的机会。于是，google引入了Sytem Server watchdog机制。这个机制来监控核心服务和核心线程是否卡住。

即SWT与普通ANR不同的是用来检测System Server系统进程的，如果该进程卡顿时间过长，会触发系统重启机制。

最开始设计只是在main looper 里面执行register 的monitor 对象 的monitor 方法. 后续Google 改进，通过HandlerChecker 来达成，在HandlerChecker 中审查注入的montior 对象是否能快速执行。即在foreground thread 来执行register 的monitor 对象，而对于其他的线程，则是审查规定时间内是否可以达到idle，不是一直卡死在某个message执行上。需要注意的是, SystemServer Watchdog启动是在SystemServer init 的后期, 如果SystemServer 在init 的过程中卡死了，那么就意味着watchdog 不会有任何的作用.