Android 如何处理Anr (借用Logcat和Trace 日志）_runnable造成的anr

1.Anr的基础知识

在开发中，遇到anr 的原因会有：

• 主线程频繁进行耗时的IO操作：如数据库读写
• 多线程操作的死锁，主线程被block；
• 主线程被Binder 对端block；
• System Server中WatchDog出现ANR；
• service binder的连接达到上线无法和和System Server通信
• 系统资源已耗尽（管道、CPU、IO）

当发生Anr时，系统会记录以下信息：

• 各个进程的cpu使用情况
• cpu的负载
• IO Wait
• traces文件。

接下来，通过一个输入事件没有响应的案例来，借用loagcat和trace 文件 分析。

2.编写一个Anr的案例

通过Studio编写以下代码：(来源网络)

public class MainActivity extends AppCompatActivity {
    private static final String TAG = "MainActivity";
    private TextView testText;
    @Override
    protected void onCreate(Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);
        setContentView(R.layout.activity_main);
        initView();
        Log.d(TAG, "onCreate start");
    }
    @Override
    protected void onPause() {
        super.onPause();
        try {
            Log.d(TAG, "onPause 准备sleep9秒");
            Thread.sleep(9000);
            Log.d(TAG, "onPause sleep9秒完成");
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }

    @Override
    protected void onStop() {
        super.onStop();
        Log.d(TAG, "onStop start");
        try {
            Log.d(TAG, "onStop 准备sleep9秒");
            Thread.sleep(9000);
            Log.d(TAG, "onStop sleep9秒完成");
        } catch (InterruptedException e) {
            e.printStackTrace();
        }

    }

    private void initView() {
        Button btnTest = findViewById(R.id.btn_test);
        testText = findViewById(R.id.tv_test);
        btnTest.setOnClickListener(new View.OnClickListener() {
            @Override
            public void onClick(View view) {
                testSleep();
            }
        });

    }

    public void testSleep() {
        //10s之后本应该进行更新ui操作，但是由于此时主线程处于休眠状态，因此待主线程结束休眠之后才会进行更新ui操作
        new Handler().postDelayed(new Runnable() {
            @Override
            public void run() {
                Log.d(TAG, "准备更新text");
                testText.setText("update btn text");
                Log.d(TAG, "更新text完成");
            }
        }, 10000);
        
        try {
            Log.d(TAG, "准备sleep30秒");
            Thread.sleep(30000);
            Log.d(TAG, "sleep30秒完成");
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        Log.d(TAG, "first update");
        testText.setText("This is the first update");
    }
}
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
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70

点击按钮，滑动屏幕或者点击Back键，等待几秒则会出现anr的弹窗。

3. 借用 logcat日志和trace文件分析Anr

获取logcat的日志文件

当app运行程序的时候，开启命令行。

首先，在打开命令行(未配置adb全路径，请在sdk中打开命令行) 下执行：
adb logcat -b all -v time >.\anr_test.log，如下图所示：

解释：

• -b all ：抓取全部事件日志
• -v time: 在log中加入每条log发生的时间
• .\anr_test.log：当前目录下记录日志的文件

发生anr 后，执行Ctrl+c 操作，结束日志抓取。

最终，日志会存储在执行cmd 命令所在目录下的anr_test.log文件中，如下图所示:

接下来，通过编辑器打开anr_test.log日志，寻找logcat的anr事件。

在anr_test.log中检索event log和 system log 事件：

通过event log 检索 am_anr ：

11-02 11:32:16.915 I/am_anr  ( 1753): [0,23694,com.miniwan.test.myapplication,820559686,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: 22.  Wait queue head age: 5729.4ms.)]

1
2

am_anr 的结构格式：[User ,pid ,Package Name,Flags ,reason] 。更多event log的资料，请阅读Android EventLog。

从上可知：

• 11-02 11:32:16：是anr发生时间
• com.miniwan.test.myapplication：是发生anr程序的包名
• 23694：是发生anr的进程 id
• Input dispatching timed out： 是anr的原因

通过system log , 继续检索ANR in关键字，能找到进一步更详细的信息：

11-02 11:32:29.407 E/ActivityManager( 1753): ANR in com.miniwan.test.myapplication (com.miniwan.test.myapplication/.MainActivity) 
11-02 11:32:29.407 E/ActivityManager( 1753): PID: 23694 //进程id
11-02 11:32:29.407 E/ActivityManager( 1753): 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: 22.  Wait queue head age: 5729.4ms.) //发生anr的原因,这里是输入事件没有响应
11-02 11:32:29.407 E/ActivityManager( 1753): Parent: com.miniwan.test.myapplication/.MainActivity
11-02 11:32:29.407 E/ActivityManager( 1753): Load: 0.0 / 0.0 / 0.0  //Load表明是1分钟,5分钟,15分钟CPU的负载
11-02 11:32:29.407 E/ActivityManager( 1753): CPU usage from 0ms to 12458ms later (2021-11-02 11:32:16.860 to 2021-11-02 11:32:29.318): // ANR后CPU的使用情况 ======later是标志
11-02 11:32:29.407 E/ActivityManager( 1753):   0.6% 1366/media.codec: 0.4% user + 0.2% kernel / faults: 62207 minor 60 major
11-02 11:32:29.407 E/ActivityManager( 1753):   0.9% 23694/com.miniwan.test.myapplication: 0.5% user + 0.4% kernel / faults: 2693 minor 5 major // 当前进程的cpu 使用情况    
//......省略部分日志
11-02 11:32:29.407 E/ActivityManager( 1753):   0.1% 12039/kworker/u17:0-dwc_wq
11-02 11:32:29.407 V/java.lang.ASSERT( 1753): copyAnr filePath = /data/anr/anr_2021-11-02-11-32-17-657 // 
1
2
3
4
5
6
7
8
9
10
11

从上可知：

• 进程Id为23694且包名为com.miniwan.test.myapplication 的程序发生Anr ，是因为输入事件没有响应导致的。

• Wait queue length: 22是指前面还有 22个事件等待处理。

• Load: 0.0 / 0.0 / 0.0 //是指 在 1分钟,5分钟,15分钟CPU的负载。

• 从上面数据看没有IO wait 或者cpu使用不合理的地方。

当找到anr 发生原因，后需要借助trace.txt 进一步分析。

获取Trace.txt 文件

打开cmd命令行，输入adb bugreport 执行。会在命令所在的目录，生成对应的压缩文件。

若是没有生成，则在android studio的Device File Explorer的bugreports目录下看到，再拷贝出来。

根据anr发生的时间点找到对应的bugreport压缩文件。

在bugreport压缩包中，bugreport_xxxx.txt也是可以查看到记录的logcat 事件，和执行adb logcat -b all -v time >.\anr_test.log类似，如下图所示：

解压后，在FS/data/anr下找到对应事件的trace日志，如下图所示：

通过编辑器，打开该trace文件，根据进程id(23694)和发生时间点(11-02 11:32:16)找到相应的信息：

----- pid 23694 at 2021-11-02 11:32:17 -----
Cmd line: com.miniwan.test.myapplication //程序的包名
Build fingerprint: 'OPPO/PCLM50/OP4AB5:10/QKQ1.200216.002/1609877348:user/release-keys'
ABI: 'arm64'
Build type: optimized
Zygote loaded classes=9847 post zygote classes=539
//.....省略部分日志 
"main" prio=5 tid=1 Sleeping  //这里主线程是tid唯一标识为1， sleep是沉睡状态
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x71925cf0 self=0x7dc7a10800
  | sysTid=23694 nice=-10 cgrp=default sched=0/0 handle=0x7e4decaed8 //主线程的id是和主进程的id一致
  | state=S schedstat=( 377724687 71579581 186 ) utm=31 stm=6 core=7 HZ=100
  | stack=0x7fc5112000-0x7fc5114000 stackSize=8192KB
  | held mutexes=
  at java.lang.Thread.sleep(Native method)
  - sleeping on <0x02cd17eb> (a java.lang.Object)
  at java.lang.Thread.sleep(Thread.java:440)
  - locked <0x02cd17eb> (a java.lang.Object) //持有0x02cd17eb这个锁,在沉睡
  at java.lang.Thread.sleep(Thread.java:356)
  at com.miniwan.test.myapplication.MainActivity.testSleep(MainActivity.java:79)
  at com.miniwan.test.myapplication.MainActivity$1.onClick(MainActivity.java:58)
  at android.view.View.performClick(View.java:7377)
  at com.google.android.material.button.MaterialButton.performClick(MaterialButton.java:967)
  at android.view.View.performClickInternal(View.java:7339)
  at android.view.View.access$3900(View.java:823)
  at android.view.View$PerformClick.run(View.java:28258)
  at android.os.Handler.handleCallback(Handler.java:883)
  at android.os.Handler.dispatchMessage(Handler.java:100)
  at android.os.Looper.loop(Looper.java:238)
  at android.app.ActivityThread.main(ActivityThread.java:7890)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:492)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:983)

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

根据以上代码走向，最后锁定在MainActivity#testSleep()方法中，持有了锁在沉睡，导致主进程在沉睡。当用户点击back键，系统进程am 通过binder 通信到主进程中，但间隔5秒都没有收到回执，系统进程抛出anr。

归纳总结：

• 当发生anr的时候，首先通过logcat的日志 ，找到event(am_anr)和system(即anr in)的log信息，分析处anr发生原因（IO wait、输入事件没响应、死锁、cpu紧张等等）
• 最后，借助trace 文件，根据进程id,包名等信息，查看当时各个线程代码走向，找到代码问题所在处。

---

参考：

• 在命令行下过滤adb logcat的输出
• Android 性能优化之ANR 多个案例
• Android ANR日志分析指南