Android 如何处理Anr (借用Logcat和Trace 日志)

Posted 新根

tags:

篇首语:本文由小常识网(cha138.com)小编为大家整理,主要介绍了Android 如何处理Anr (借用Logcat和Trace 日志)相关的知识,希望对你有一定的参考价值。

文章目录

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");
    

点击按钮,滑动屏幕或者点击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.)]

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

从上可知:

  • 进程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)

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

归纳总结

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

参考

以上是关于Android 如何处理Anr (借用Logcat和Trace 日志)的主要内容,如果未能解决你的问题,请参考以下文章

Android ANR 分析 /data/anr/trace.txt 该文件记录了产生ANR的函数堆栈可以帮助分析

Android 通过logcat查看crash 或者anr日志

如何处理尝试捕获异常android

Android、IOS、网站图片如何处理?

Android/Parse-如何处理来自 ParseQuery 的多个回调

如何处理Android中的长按