Android ANR分析

XingJimmy
8,680 阅读5分钟

ANR介绍

ANR，是“Application Not Responding”的缩写，即“应用程序无响应”。系统会向用户显示一个对话框，用户可以选择“等待”而让程序继续运行，也可以选择“强制关闭”。

发生ANR条件

  • 在5秒内没有响应输入的事件（例如，按键按下，屏幕触摸）
  • BroadcastReceiver在10秒内没有执行完毕
  • Service在特定时间内（20秒内）无法处理完成

造成ANR的原因很多，主线程耗时操作，如网络连接、IO读写、线程同步锁，注意，产生这种ANR的前提是要有输入事件，如果用户没有触发任何输入事件，即便是主线程阻塞了，也不会产生ANR。

来看段示例代码

public class AnrActivity extends Activity {
    @Override
    protected void onCreate(@Nullable Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);
        setContentView(R.layout.content_main);

        start();
    }
    private synchronized void start() {
        try {
            while (true) {
                Thread.sleep(10000);
            }
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}
  • 启动时，会发生ANR吗？不会，因为没有任何输入事件
  • 点击返回按键，会发生ANR吗？会

如何获取ANR日志

旧版本系统

  • ANR的log都是放在data/anr/traces.txt

  • adb shell cat /data/anr/traces.txt > /.../traces.txt 可以导出日志文件

新版本系统

  • /data/anr/目录没有traces.txt，而是anr_XXX多个文件，且使用adb shell cat命令会报错，提示permission denied。
  • 使用adb bugreport <zip_file> 在电脑当前目录生成名字为zip_file的zip文件

简单分析ANR日志

  • 前2行 ANR发生的进程id、时间和进程名称。
----- pid 24277 at 2019-09-16 16:23:19 -----
Cmd line: com.example.androidtest
  • 内存等信息
Build fingerprint: 'google/walleye/walleye:9/PQ1A.190105.004/5148680:user/release-keys'
ABI: 'arm64'
Build type: optimized
Zygote loaded classes=10643 post zygote classes=81
Intern table: 73306 strong; 365 weak
JNI: CheckJNI is on; globals=602 (plus 23 weak)
Libraries: /system/lib64/libandroid.so /system/lib64/libcompiler_rt.so /system/lib64/libjavacrypto.so /system/lib64/libjnigraphics.so /system/lib64/libmedia_jni.so /system/lib64/libsoundpool.so /system/lib64/libwebviewchromium_loader.so libjavacore.so libopenjdk.so (9)
Heap: 33% free, 1760KB/2MB; 42897 objects
......
suspend all histogram:	Sum: 133us 99% C.I. 1us-46us Avg: 8.866us Max: 46us
  • 具体线程信息
"Signal Catcher" daemon prio=5 tid=3 Runnable
  | group="system" sCount=0 dsCount=0 flags=0 obj=0x13dc0000 self=0x78a0a16400
  | sysTid=24283 nice=0 cgrp=default sched=0/0 handle=0x789a1ff4f0
  | state=R schedstat=( 11415990 257604 4 ) utm=0 stm=0 core=6 HZ=100
  | stack=0x789a104000-0x789a106000 stackSize=1009KB
  | held mutexes= "mutator lock"(shared held)
  native: #00 pc 00000000003c7324  /system/lib64/libart.so (art::DumpNativeStack(std::__1::basic_ostream<char, std::__1::char_traits<char>>&, int, BacktraceMap*, char const*, art::ArtMethod*, void*, bool)+220)
  native: #01 pc 0000000000495d80  /system/lib64/libart.so (art::Thread::DumpStack(std::__1::basic_ostream<char, std::__1::char_traits<char>>&, bool, BacktraceMap*, bool) const+352)
  native: #02 pc 00000000004afd1c  /system/lib64/libart.so (art::DumpCheckpoint::Run(art::Thread*)+844)
  native: #03 pc 00000000004a8a5c  /system/lib64/libart.so (art::ThreadList::RunCheckpoint(art::Closure*, art::Closure*)+476)
  native: #04 pc 00000000004a7eac  /system/lib64/libart.so (art::ThreadList::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char>>&, bool)+1036)
  native: #05 pc 00000000004a79b4  /system/lib64/libart.so (art::ThreadList::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char>>&)+884)
  native: #06 pc 0000000000477864  /system/lib64/libart.so (art::Runtime::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char>>&)+188)
  native: #07 pc 000000000048372c  /system/lib64/libart.so (art::SignalCatcher::HandleSigQuit()+1372)
  native: #08 pc 0000000000482420  /system/lib64/libart.so (art::SignalCatcher::Run(void*)+256)
  native: #09 pc 0000000000083194  /system/lib64/libc.so (__pthread_start(void*)+36)
  native: #10 pc 00000000000233bc  /system/lib64/libc.so (__start_thread+68)
  (no managed stack frames)

说明

  • 第一行

线程名(如有daemon则代表守护线程)

prio: 线程优先级

tid: 线程号

线程当前状态 Runnable

  • 第二行

group: 线程所属的线程组

sCount: 线程挂起次数

dsCount: 用于调试的线程挂起次数

obj: 当前线程关联的java线程对象

self: 当前线程地址

  • 第三行

sysTid: 线程真正意义的tid

nice: 调度优先级 nice值越小则优先级越高

cgrp: 线程所属的进程调度组

sched: 调度策略

handle: 函数处理地址

  • 第四行

state: 线程状态

schedstat: CPU调度时间统计

schedstat括号中的3个数字依次是Running、Runable、Switch，

  • Running时间：CPU运行的时间，单位ns
  • Runable时间：RQ队列的等待时间，单位ns
  • Switch次数：CPU调度切换次数

utm/stm: 用户态/内核态的CPU时间

utm: 该线程在用户态所执行的时间，单位是jiffies，jiffies定义为sysconf(_SC_CLK_TCK)，默认等于10ms。

stm: 该线程在内核态所执行的时间，单位是jiffies，默认等于10ms。

utm + stm = schedstat第一个参数值。

core: 该线程的最后运行所在核

HZ: 时钟频率

  • 第五行

stack：线程栈的地址区间

stackSize：栈的大小

  • 第六行

mutex: 所持有mutex类型，有独占锁exclusive和共享锁shared两类

具体分析下ANR的日志

先模拟一个会引起ANR的代码

public class AnrActivity extends Activity {
    @Override
    protected void onCreate(@Nullable Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);
        setContentView(R.layout.content_main);

        findViewById(R.id.txt).setOnClickListener(new View.OnClickListener() {
            @Override
            public void onClick(View v) {
                stop();
            }
        });
        new Thread(new Runnable() {
            @Override
            public void run() {
                start();
            }
        }).start();
    }

    private synchronized void start() {
        long startTime = System.currentTimeMillis();
        while (true) {
            long stopTime = System.currentTimeMillis();
            if ((stopTime - startTime) / 1000 >= 10) {
                break;
            }
        }
    }

    private synchronized void stop() {
        Toast.makeText(AnrActivity.this, "stop", Toast.LENGTH_SHORT).show();
    }
}

"main" prio=5 tid=1 Blocked
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x75586910 self=0x78a0a14c00
  | sysTid=24277 nice=-10 cgrp=default sched=0/0 handle=0x79264f2548
  | state=S schedstat=( 289217601 7166871 217 ) utm=25 stm=3 core=6 HZ=100
  | stack=0x7fe93cd000-0x7fe93cf000 stackSize=8MB
  | held mutexes=
  at com.example.androidtest.anr.AnrActivity.stop(AnrActivity.java:-1)
  - waiting to lock <0x06b3ced2> (a com.example.androidtest.anr.AnrActivity) held by thread 13
  at com.example.androidtest.anr.AnrActivity.access$000(AnrActivity.java:12)
  at com.example.androidtest.anr.AnrActivity$1.onClick(AnrActivity.java:21)
  at android.view.View.performClick(View.java:6597)
  at android.view.View.performClickInternal(View.java:6574)
  at android.view.View.access$3100(View.java:778)
  at android.view.View$PerformClick.run(View.java:25885)
  at android.os.Handler.handleCallback(Handler.java:873)
  at android.os.Handler.dispatchMessage(Handler.java:99)
  at android.os.Looper.loop(Looper.java:193)
  at android.app.ActivityThread.main(ActivityThread.java:6718)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:493)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:858)
  • "main" prio=5 tid=1 Blocked 主线程Blocked
  • held mutexes= at com.example.androidtest.anr.AnrActivity.stop(AnrActivity.java:-1) ANR发生在stop方法
  • waiting to lock <0x06b3ced2> (a com.example.androidtest.anr.AnrActivity) held by thread 13 在获取线程13的锁<0x06b3ced2>而等待

我们知道tid代表线程id，那么找到tid=13的线程信息

"Thread-2" prio=5 tid=13 Suspended
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x12c7ae18 self=0x78a0af1800
  | sysTid=24295 nice=0 cgrp=default sched=0/0 handle=0x788a5ff4f0
  | state=S schedstat=( 7380427077 3743221 140 ) utm=737 stm=0 core=5 HZ=100
  | stack=0x788a4fc000-0x788a4fe000 stackSize=1041KB
  | held mutexes=
  at com.example.androidtest.anr.AnrActivity.start(AnrActivity.java:35)
  - locked <0x06b3ced2> (a com.example.androidtest.anr.AnrActivity)
  at com.example.androidtest.anr.AnrActivity.access$100(AnrActivity.java:12)
  at com.example.androidtest.anr.AnrActivity$2.run(AnrActivity.java:27)
  at java.lang.Thread.run(Thread.java:764)

可见，在start方法中锁<0x06b3ced2>，导致主线程无法获取。

avatar
文章
阅读
粉丝