喜好

喜好检索

生活 蔬菜

蔬菜大全

思考

见闻与录

BT技术

BT蓝牙技术

标签

Android 28

Life 5

JS 2

Linux 6

Linux_C 1

C 1

Windows_C 2

Cpp 1

Windows 5

Java 4

Json 1

Shell 1

English 2

House 1

月历 1

蔬菜 1

Analysis 3

Supplicant 2

Graphviz 2

Tool 9

Wifi 11

Vendor 5

AOSP 17

Bin 1

Sh 2

MacOS 3

Wechat 1

Tip 1

Think 1

AndroidStudio 1

Python 3

Tushare 1

git 1

Jar 2

Flutter 1

Website 7

Git 1

Protocol 2

IT 1

Sort 1

Color 1

Swift 1

IOS 1

Bat 1

Math 2

GB 1

甘特图 1

Mtk 1

Qcom 3

markdown 1

百度 1

无线网络 1

代码 1

Code 2

Anaconda 1

ANR 1

GPS 2

SUPL 1

阿里云盘 1

时序绘画 1

Stall 1

Modem 1

BT 1

蓝牙 1

QXDM 1

ANR分析 2023年04月12日

    简介

    ANR简介

    https://blog.csdn.net/qq_27672101/article/details/131257787

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

    ANR类型

    InputDispatchingTimedOut

    InputDispatchingTimedOut：应用程序主线程在5s内没有完成用户的input事件

    ServiceTimeout

    ServiceTimeout：应用程序没有执行完成service的bind/create/start/destroy/unbind操作，前台服务20s超时，后台服务200s超时

    BroadcastTimeout

    BroadcastTimeout：应用程序在规定时间内没有执行完成onReceive操作，前台广播10s超时，后台广播60s超时

    ContentProviderTimeout

    ContentProviderTimeout：应用程序在20s内没有执行完成ContentProvider相关操作

    ANR产生原因

    系统原因

    系统原因：由于Kernel/Framework/Driver等存在问题，导致系统不稳定最终表现出ANR

    应用原因

    应用原因：主线程死锁、阻塞或者性能低下，需避免将耗时操作放在主线程

    如何理解ANR

    Java进程中主线程主要做如下两件事：

    1. Activity已经View相关在该线程中被绘制，以及事件（类似点击事件）响应等，这些事情都跟UI相关，所以主线程又叫做UI线程；
    2. 轮训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。
    • MTK DB
    MTK通过db的方式来记录系统发生的一切JE/NE/ANR相关的堆栈，如下图，但是需要通过mtk的专用工具才能解析。
    • Traces 
      平台的AP日志中有专门traces文件夹，该文件夹存放了每一次ANR的堆栈调用，系统信息，文件格式为xx_xxx-xx_anr_xx_xx_xx。

    ANR分析

    ANR分析流程

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

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

    展锐平台ANR

    MTK平台ANR

    • MTK旧

    • MTK新

    确认ANR类型和相关信息

    通过_MainLog定位

    关键字 【ANR in】

    关键字 【cmd line: ANR应用包名称】

    通过_EnventLog定位

    关键字 【am_anr】
    
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)]

    初步查看ANR主线程堆栈信息

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

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

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

    ANR堆栈信息结构

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

    ANR发生前后_CPU和MEM内存_情况

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

    Signal Catcher线程是抓取Java虚拟机堆栈的线程

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

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

    ANR发生进程其他线程堆栈信息

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

    "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=
  
  "main【线程名】" prio【线程优先级】=5 tid【线程内部id】=1 Native【线程状态: Native|Blocked 】
  | group【线程所属的线程组】="main" sCount【线程挂起次数】=1 ucsCount=0 flags=1 obj【当前线程关联的java线程对象】=0x735086e8 self【当前线程地址】=0xb4000071e8c707b0
  | sysTid【线程真正意义上的tid】=1329 nice=0【调度有优先级】 cgrp【进程所属的进程调度】=default sched【调度策略】=1073741824/0 handle【函数处理地址】=0x732dad44f8 
  | state【线程状态】=S schedstat【CPU调度时间统计】=( 136542970431 292470333243 553823 ) utm【用户态CPU时间】=8774 stm【内核态的CPU时间】=4879 core【该线程的最后运行所在核】=3 HZ=100
  | stack【线程栈的地址区间】=0x7febede000-0x7febee0000 stackSize【栈的大小】=8188KB
  | held mutexes【所持有mutex类型】=

  
#线程名: main（如有daemon则代表守护线程)
#线程名"main"：通常为主线程，这个跟group不一样，有些子线程的group也是main，但他们不是主线程
#线程名"Binder"：通常为binder子线程

#prio: 线程优先级

#tid: 线程内部id

#线程状态: NATIVE
#线程状态Native：表明该线程当前运行在native层，通常会有一些c/c++代码堆栈打印
#线程状态Blocked：表明该线程被阻塞，通常为java某个方法被卡住，或者等待某个锁的释放


#第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两类

    ANR Waiting Channels信息

    #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 ---

    常见ANR主线程堆栈案例

    Java/Native层发生阻塞

    

#SP commit 属于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等待这把锁释放

    确定系统当前状态

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

    CPU占用率

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

    具体分析流程如下几步：

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

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

    MediaTek On-Line | Login https://online.mediatek.com/QuickStart/QS00152#QSS01631

    MediaTek On-Line | Login https://online.mediatek.com/QuickStart/QS00164#QSS01723

    内存占用率/内存泄漏

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

    Memory bound的关键特征主要如上截图三类：

    • 查看CPU INFO中的kswap进程；
    • 在android日志搜索lowmemorykiller；
    • 在kernel日志中搜索lowmemorykiller，例如：

    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阻塞