Activity#onPause方法导致的Activity pause timeout for ActivityRecord的ANR问题分析

Activity的生命周期的几个方法都是在主线程调用的，因此在这些方法中执行耗时操作并且再次点击按钮或者触摸屏幕会产生ANR。

还有一点特别需要注意的是，onPause方法中尽量不要做过多的耗时操作，一些不是关键的耗时操作可以移动到onStop方法中，ActivityStack.java类中，我们可以看到Activity的生命周期的超时时间：

    // Ticks during which we check progress while waiting for an app to launch.
    static final int LAUNCH_TICK = 500;

    // How long we wait until giving up on the last activity to pause.  This
    // is short because it directly impacts the responsiveness of starting the
    // next activity.
    private static final int PAUSE_TIMEOUT = 500;

    // How long we wait for the activity to tell us it has stopped before
    // giving up.  This is a good amount of time because we really need this
    // from the application in order to get its saved state. Once the stop
    // is complete we may start destroying client resources triggering
    // crashes if the UI thread was hung. We put this timeout one second behind
    // the ANR timeout so these situations will generate ANR instead of
    // Surface lost or other errors.
    private static final int STOP_TIMEOUT = 11 * 1000;

    // How long we wait until giving up on an activity telling us it has
    // finished destroying itself.
    private static final int DESTROY_TIMEOUT = 10 * 1000;

• onPause是500毫秒
• onStop是11秒
• onDestroy是10秒

onPause只有500毫秒，根本无法执行较多的释放清理任务，因此，我们可以将一些不是关键的耗时较多的操作放到onStop中，这样就不会在onPause中产生ANR异常，但是要注意，在Android中onPause方法是进程被杀前一定会被调用的方法，而onStop方法不一定会被调用，因此有些关键的操作是不能移动到onStop方法中的，这里实际情况中要注意权衡。

思考一个问题，PAUSE_TIMEOUT 参数在代码中是怎么使用的？

演示onPause方法耗时操作引起的ANR，在onPause方法中sleep 9秒：

    @Override
    protected void onPause() {
        super.onPause();

        try {
            Thread.sleep(1000 * 9);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }

    }

产生了ANR:

但是在onStop方法中sleep 9秒并不会引起ANR：

    @Override
    protected void onStop() {
        super.onStop();
        
        try {
            Thread.sleep(1000 * 9);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }

    }

可以立马跳转到下一个Activity，但是这个时候如果很快在新Activity中点击返回按钮就会产生ANR了。

上述onPause方法执行耗时操作引起的ANR发生时，Android Studio的Logcat的实时输出日志如下：

2021-01-05 19:15:34.473 14825-14843/com.example.javaadvanced I/le.javaadvance: Thread[3,tid=14843,WaitingInMainSignalCatcherLoop,Thread*=0xe180c410,peer=0x134c0b00,"Signal Catcher"]: reacting to signal 3
2021-01-05 19:15:34.576 14825-14843/com.example.javaadvanced I/le.javaadvance: Wrote stack traces to tombstoned
2021-01-05 19:15:37.506 14825-14825/com.example.javaadvanced I/Choreographer: Skipped 540 frames!  The application may be doing too much work on its main thread.
2021-01-05 19:15:37.524 14825-14825/com.example.javaadvanced I/System.out: find:com.example.javaadvanced.performanceOptimization.anr.ANRSecondActivity$1
2021-01-05 19:15:37.524 14825-14825/com.example.javaadvanced I/System.out: find:com.example.javaadvanced.performanceOptimization.anr.ANRSecondActivity$1
2021-01-05 19:15:37.524 14825-14825/com.example.javaadvanced I/System.out: find:com.example.javaadvanced.performanceOptimization.anr.ANRSecondActivity$2
2021-01-05 19:15:37.526 14825-14825/com.example.javaadvanced I/System.out: find:com.example.javaadvanced.performanceOptimization.anr.ANRSecondActivity$2
2021-01-05 19:15:37.526 14825-14825/com.example.javaadvanced I/System.out: find:com.example.javaadvanced.performanceOptimization.anr.ANRSecondActivity$3
2021-01-05 19:15:37.526 14825-14825/com.example.javaadvanced I/System.out: find:com.example.javaadvanced.performanceOptimization.anr.ANRSecondActivity$3
2021-01-05 19:15:37.534 14825-14900/com.example.javaadvanced I/OpenGLRenderer: Davey! duration=9032ms; Flags=0, IntendedVsync=11964731234647, Vsync=11973731234287, OldestInputEvent=9223372036854775807, NewestInputEvent=0, HandleInputStart=11973739223220, AnimationStart=11973739282520, PerformTraversalsStart=11973742394620, DrawStart=11973742829520, SyncQueued=11973742999020, SyncStart=11973745896320, IssueDrawCommandsStart=11973746002220, SwapBuffers=11973756716220, FrameCompleted=11973766721320, DequeueBufferDuration=551600, QueueBufferDuration=6738200, GpuCompleted=0, 

分析onPause方法执行耗时操作引起的ANR，从两个方面：分析traces.txt文件、分析log日志文件。

分析traces.txt文件

使用adb命令查看traces.txt文件，
如果提示：

'adb' 不是内部或外部命令，也不是可运行的程序或批处理文件。

则需要配置adb的环境变量。

如果执行 su root 命令时提示：

/system/bin/sh: su: inaccessible or not found

则不要使用名称带Google Play的模拟器，使用名称带Google APIs的模拟器即可。

执行下面命令：
1.adb shell
进入adb shell
2.cd data/anr
进入anr目录
3.ls
查看目录下的文件：

可以看到只有一个命名为anr_2021-01-06-09-07-33-098的文件，并不是命名为traces.txt，而是按照anr_开头后面跟着日期和时间的格式命名的。

执行： chmod 777 anr_2021-01-06-09-07-33-098
否则后续执行adb pull /data/anr/anr_2021-01-06-09-07-33-098时会报错：
bash adb: error: failed to copy ... remote open failed: Permission denied

4.先退出adb shell (Ctrl +D)
然后执行 adb pull /data/anr/anr_2021-01-06-09-07-33-098
这样这份anr文件就复制到了执行命令时在的目录下。

打开anr_2021-01-06-09-07-33-098文件，进行分析。
先搜索关键字 “main”，可以看到这部分内容如下：

"main" prio=5 tid=1 Sleeping
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x71a0f6f8 self=0xdeb42a10
  | sysTid=4341 nice=-10 cgrp=top-app sched=0/0 handle=0xed0b0478
  | state=S schedstat=( 1275842556 336345269 743 ) utm=37 stm=89 core=2 HZ=100
  | stack=0xff55d000-0xff55f000 stackSize=8192KB
  | held mutexes=
  at java.lang.Thread.sleep(Native method)
  - sleeping on <0x053103fc> (a java.lang.Object)
  at java.lang.Thread.sleep(Thread.java:442)
  - locked <0x053103fc> (a java.lang.Object)
  at java.lang.Thread.sleep(Thread.java:358)
  at com.example.javaadvanced.performanceOptimization.anr.ANRMainActivity.onPause(ANRMainActivity.java:95)
  at android.app.Activity.performPause(Activity.java:8174)
  at android.app.Instrumentation.callActivityOnPause(Instrumentation.java:1510)
  at android.app.ActivityThread.performPauseActivityIfNeeded(ActivityThread.java:4735)
  at android.app.ActivityThread.performPauseActivity(ActivityThread.java:4696)
  at android.app.ActivityThread.handlePauseActivity(ActivityThread.java:4647)
  at android.app.servertransaction.PauseActivityItem.execute(PauseActivityItem.java:46)
  at android.app.servertransaction.TransactionExecutor.executeLifecycleState(TransactionExecutor.java:176)
  at android.app.servertransaction.TransactionExecutor.execute(TransactionExecutor.java:97)
  at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2066)
  at android.os.Handler.dispatchMessage(Handler.java:106)
  at android.os.Looper.loop(Looper.java:223)
  at android.app.ActivityThread.main(ActivityThread.java:7656)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:592)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:947)

可以清楚的看到是由于ANRMainActivity的onPause方法执行Thread.sleep导致的ANR。

这个ANR问题比较简单，就这么轻松的解决了！

分析log日志文件

Android 的log日志文件存在哪个路径？
/data/system/dropbox/

执行：
1.su root
2.cd /data/system/dropbox/
3.ls -l
可以看到很多各种类型的log文件：

-rw------- 1 system system   550 2021-01-06 09:07 SYSTEM_BOOT@1609924026415.txt
-rw------- 1 system system  1472 2021-01-06 09:07 SYSTEM_FSCK@1609924026427.txt
-rw------- 1 system system 24700 2021-01-06 09:07 data_app_anr@1609924054852.txt.gz
-rw------- 1 system system    51 2021-01-06 09:27 event_data@1609925269822.txt
-rw------- 1 system system    39 2021-01-06 09:57 event_data@1609927053555.txt
-rw------- 1 system system    34 2021-01-06 09:07 event_log@1609924029033.txt
-rw------- 1 system system  1747 2021-01-06 09:06 system_app_strictmode@1609924002953.txt
-rw------- 1 system system  1848 2021-01-06 09:06 system_app_strictmode@1609924002958.txt
-rw------- 1 system system  1712 2021-01-06 09:06 system_app_strictmode@1609924002964.txt
-rw------- 1 system system  1781 2021-01-06 09:06 system_app_strictmode@1609924002968.txt
-rw------- 1 system system  2910 2021-01-06 09:06 system_app_strictmode@1609924012896.txt
-rw------- 1 system system  1046 2021-01-06 10:00 system_app_strictmode@1609927200233.txt
-rw------- 1 system system  1301 2021-01-06 09:06 system_server_strictmode@1609923995203.txt
-rw------- 1 system system  1419 2021-01-06 09:06 system_server_strictmode@1609923995205.txt
-rw------- 1 system system  1541 2021-01-06 09:06 system_server_strictmode@1609923995206.txt

	...

-rw------- 1 system system  1226 2021-01-06 09:06 system_server_wtf@1609924003647.txt
-rw------- 1 system system  1223 2021-01-06 09:06 system_server_wtf@1609924005361.txt
-rw------- 1 system system  1252 2021-01-06 09:06 system_server_wtf@1609924006331.txt
-rw------- 1 system system  1252 2021-01-06 09:06 system_server_wtf@1609924006335.txt

上面展示了其中的一部分。

其中anr的log文件是压缩类型的： data_app_anr@1609924054852.txt.gz
先解压：gzip -d data_app_anr@1609924054852.txt.gz
得到 data_app_anr@1609924054852.txt 文件：

-rw------- 1 system system    550 2021-01-06 09:07 SYSTEM_BOOT@1609924026415.txt
-rw------- 1 system system   1472 2021-01-06 09:07 SYSTEM_FSCK@1609924026427.txt
-rwxrwxrwx 1 root   root   196623 2021-01-06 09:07 data_app_anr@1609924054852.txt
-rw------- 1 system system     51 2021-01-06 09:27 event_data@1609925269822.txt
-rw------- 1 system system     39 2021-01-06 09:57 event_data@1609927053555.txt

...

4.执行 chmod 777 data_app_anr@1609924054852.txt.gz
然后退出adb shell，然后执行
adb pull /data/system/dropbox/data_app_anr@1609924054852.txt

却提示：

adb: error: failed to stat remote object '/data/system/dropbox/data_app_anr@1609924054852.txt': Permission denied

可能这个文件夹比较特殊，chmod 777 后还是不能 执行adb pull 拷贝出文件。

换另外的办法，重新进入/data/system/dropbox/，然后执行
cp data_app_anr@1609924054852.txt /sdcard/data_app_anr@1609924054852.txt
把这个文件拷贝到sd卡中，然后退出adb shell，然后执行
adb pull /sdcard/data_app_anr@1609924054852.txt
把这个anr的log文件拷贝到了命令行在的目录下。

打开data_app_anr@1609924054852.txt，进行分析。
搜索关键字：CPU usage
可以看到：

84% TOTAL: 9.9% user + 70% kernel + 0.6% iowait + 2.8% softirq

cpu使用率非常高，其中内核占了70%，

继续搜索 “main”，看main线程做了操作：

"main" prio=5 tid=1 Sleeping
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x71a0f6f8 self=0xdeb42a10
  | sysTid=4341 nice=-10 cgrp=top-app sched=0/0 handle=0xed0b0478
  | state=S schedstat=( 1275842556 336345269 743 ) utm=37 stm=89 core=2 HZ=100
  | stack=0xff55d000-0xff55f000 stackSize=8192KB
  | held mutexes=
  at java.lang.Thread.sleep(Native method)
  - sleeping on <0x053103fc> (a java.lang.Object)
  at java.lang.Thread.sleep(Thread.java:442)
  - locked <0x053103fc> (a java.lang.Object)
  at java.lang.Thread.sleep(Thread.java:358)
  at com.example.javaadvanced.performanceOptimization.anr.ANRMainActivity.onPause(ANRMainActivity.java:95)
  at android.app.Activity.performPause(Activity.java:8174)
  at android.app.Instrumentation.callActivityOnPause(Instrumentation.java:1510)
  at android.app.ActivityThread.performPauseActivityIfNeeded(ActivityThread.java:4735)
  at android.app.ActivityThread.performPauseActivity(ActivityThread.java:4696)
  at android.app.ActivityThread.handlePauseActivity(ActivityThread.java:4647)
  at android.app.servertransaction.PauseActivityItem.execute(PauseActivityItem.java:46)
  at android.app.servertransaction.TransactionExecutor.executeLifecycleState(TransactionExecutor.java:176)
  at android.app.servertransaction.TransactionExecutor.execute(TransactionExecutor.java:97)
  at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2066)
  at android.os.Handler.dispatchMessage(Handler.java:106)
  at android.os.Looper.loop(Looper.java:223)
  at android.app.ActivityThread.main(ActivityThread.java:7656)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:592)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:947)

这部分内容和traces文件中的内容是一样的。即是由于ANRMainActivity的onPause方法执行Thread.sleep导致的ANR。

主线程做了耗时操作一定会引发ANR吗

在主线程做耗时操作并不一定会引发ANR，除非在这个耗时操作的过程中有用户交互，即要有用户点击屏幕按钮或者触摸屏幕后Android系统没有响应，才会引起ANR。因为ANR的意思是应用没有响应，如果用户都没有请求输入(即没有点击屏幕或者触摸屏幕等)，那自然不需要系统有响应。所以耗时操作不一定会引起ANR，因为可能系统根本就不需要响应。

参考：
onPause耗时导致Activity pause timeout for ActivityRecord的ANR分析

Android ANR 分析与解决
Android ANR：原理分析及解决办法