稳定性 框架问题 疑难问题

AMS缺陷导致的系统低概率重启问题

一例经典的AMS BUG导致的系统低概率重启问题

发布日期 2019-07-12

一. 问题现象

问题很典型，我们先来看一下日志打印的调用栈。


2019-06-27 07:14:46 system_server_crash (text, 1021 bytes)
Process: system_server
java.lang.IndexOutOfBoundsException: Invalid index 8, size is 8
at java.util.ArrayList.throwIndexOutOfBoundsException(ArrayList.java:255)
at java.util.ArrayList.get(ArrayList.java:308)
at com.android.server.am.ActivityStack.finishTopRunningActivityLocked(ActivityStack.java:2901)
at com.android.server.am.ActivityStackSupervisor.finishTopRunningActivityLocked(ActivityStackSupervisor.java:2891)
at com.android.server.am.ActivityManagerService.handleAppCrashLocked(ActivityManagerService.java:12483)
at com.android.server.am.ActivityManagerService.killAppAtUsersRequest(ActivityManagerService.java:12434)
at com.android.server.am.AppNotRespondingDialog$1.handleMessage(AppNotRespondingDialog.java:114)
at android.os.Handler.dispatchMessage(Handler.java:102)
at android.os.Looper.loop(Looper.java:148)
at android.os.HandlerThread.run(HandlerThread.java:61)
at com.android.server.ServiceThread.run(ServiceThread.java:46)

很明显，从调用栈可以看出是在某个应用发生ANR的时候弹出对话框的过程导致手机重启。

来看看调用栈上的finishTopRunningActivityLocked()方法：

finishTopRunningActivityLocked

在Android源码里面有大量方法名为xxxLock, 其含义是指该方法是非线程安全的, 所有调用该方法的地方一定是加过锁的. 也就是说 finishTopRunningActivityLocked()该方法一定是被AMS锁synchronized所保护, 既然同步锁保护, 为何还会出现mTaskHistory变量获取过程为出现数据越界的问题? 此问题是一个低概率问题，接下来, 开始一步步剖析, 解开这个谜团.

二. 问题分析

分析重启异常问题，最重要的是从时间点附近逐步分析推理整个过程。重启发生在2019-06-27 07:14:46，需要逐一遴选基于该时间点附近的关键日志。这个过程日志有很多，需要有一定的功底，对于一行静态的日志能推算出复杂系统的动态执行流程，具体筛选过程就不再一一赘述了，下面直接列出跟该问题直接相关的核心日志信息。

核心日志


//Step 1. ANR
06-27 07:14:44.015  1236  1275 E ActivityManager: ANR in com.dailyyoga.cn (com.dailyyoga.cn/.activity.PlanDetailActivity)
06-27 07:14:44.015  1236  1275 E ActivityManager: PID: 13930
06-27 07:14:44.015  1236  1275 E ActivityManager: Reason: Input dispatching timed out (Waiting because the touched window's input channel is not registered with the input dispatcher.  The window may be in the process of being removed.)

//Step 2. AS.finishTopRunningActivityLocked()
06-27 07:14:46.197    1236 1276 ActivityManager:   Force finishing activity com.dailyyoga.cn/.activity.PlanDetailActivity

// Step 3. AS.startPausingLocked()
06-27 07:14:46.206    1236 1276   W ActivityManager: Exception thrown during pause
06-27 07:14:46.206    1236 1276   W ActivityManager: android.os.DeadObjectException: Transaction failed on small parcel; remote process probably died
06-27 07:14:46.206    1236 1276   W ActivityManager:    at android.os.BinderProxy.transactNative(Native Method)
06-27 07:14:46.206    1236 1276   W ActivityManager:    at android.os.BinderProxy.transact(Binder.java:503)
06-27 07:14:46.206    1236 1276   W ActivityManager:    at android.app.ApplicationThreadProxy.schedulePauseActivity(ApplicationThreadNative.java:727)
06-27 07:14:46.206    1236 1276   W ActivityManager:    at com.android.server.am.ActivityStack.startPausingLocked(ActivityStack.java:915)
06-27 07:14:46.206    1236 1276   W ActivityManager:    at com.android.server.am.ActivityStack.finishActivityLocked(ActivityStack.java:3030)
06-27 07:14:46.206    1236 1276   W ActivityManager:    at com.android.server.am.ActivityStack.finishTopRunningActivityLocked(ActivityStack.java:2886)
06-27 07:14:46.206    1236 1276   W ActivityManager:    at com.android.server.am.ActivityStackSupervisor.finishTopRunningActivityLocked(ActivityStackSupervisor.java:2891)
06-27 07:14:46.206    1236 1276   W ActivityManager:    at com.android.server.am.ActivityManagerService.handleAppCrashLocked(ActivityManagerService.java:12483)
06-27 07:14:46.206    1236 1276   W ActivityManager:    at com.android.server.am.ActivityManagerService.killAppAtUsersRequest(ActivityManagerService.java:12434)
06-27 07:14:46.206    1236 1276   W ActivityManager:    at com.android.server.am.AppNotRespondingDialog$1.handleMessage(AppNotRespondingDialog.java:114)
06-27 07:14:46.206    1236 1276   W ActivityManager:    at android.os.Handler.dispatchMessage(Handler.java:102)
06-27 07:14:46.206    1236 1276   W ActivityManager:    at android.os.Looper.loop(Looper.java:148)
06-27 07:14:46.206    1236 1276   W ActivityManager:    at android.os.HandlerThread.run(HandlerThread.java:61)
06-27 07:14:46.206    1236 1276   W ActivityManager:    at com.android.server.ServiceThread.run(ServiceThread.java:46)

//Step 4. AS.resumeTopActivityInnerLocked()
06-27 07:14:46.209    1236 1276   I ActivityManager: Restarting because process died: ActivityRecord{909d520 u0 com.dailyyoga.cn/.FrameworkActivity t1861}

//Step 5. ASS.startSpecificActivityLocked()
06-27 07:14:46.211    1236 1276   W ActivityManager: Exception when starting activity com.dailyyoga.cn/.FrameworkActivity
06-27 07:14:46.211    1236 1276   W ActivityManager: android.os.DeadObjectException: Transaction failed on small parcel; remote process probably died
06-27 07:14:46.211    1236 1276   W ActivityManager:    at android.os.BinderProxy.transactNative(Native Method)
06-27 07:14:46.211    1236 1276   W ActivityManager:    at android.os.BinderProxy.transact(Binder.java:503)
06-27 07:14:46.211    1236 1276   W ActivityManager:    at android.app.ApplicationThreadProxy.scheduleLaunchActivity(ApplicationThreadNative.java:826)
06-27 07:14:46.211    1236 1276   W ActivityManager:    at com.android.server.am.ActivityStackSupervisor.realStartActivityLocked(ActivityStackSupervisor.java:1357)
06-27 07:14:46.211    1236 1276   W ActivityManager:    at com.android.server.am.ActivityStackSupervisor.startSpecificActivityLocked(ActivityStackSupervisor.java:1457)
06-27 07:14:46.211    1236 1276   W ActivityManager:    at com.android.server.am.ActivityStack.resumeTopActivityInnerLocked(ActivityStack.java:2058)
06-27 07:14:46.211    1236 1276   W ActivityManager:    at com.android.server.am.ActivityStack.resumeTopActivityLocked(ActivityStack.java:1605)
06-27 07:14:46.211    1236 1276   W ActivityManager:    at com.android.server.am.ActivityStack.resumeTopActivityLocked(ActivityStack.java:1588)
06-27 07:14:46.211    1236 1276   W ActivityManager:    at com.android.server.am.ActivityStack.startPausingLocked(ActivityStack.java:970)
06-27 07:14:46.211    1236 1276   W ActivityManager:    at com.android.server.am.ActivityStack.finishActivityLocked(ActivityStack.java:3030)
06-27 07:14:46.211    1236 1276   W ActivityManager:    at com.android.server.am.ActivityStack.finishTopRunningActivityLocked(ActivityStack.java:2886)
06-27 07:14:46.211    1236 1276   W ActivityManager:    at com.android.server.am.ActivityStackSupervisor.finishTopRunningActivityLocked(ActivityStackSupervisor.java:2891)
06-27 07:14:46.211    1236 1276   W ActivityManager:    at com.android.server.am.ActivityManagerService.handleAppCrashLocked(ActivityManagerService.java:12483)
06-27 07:14:46.211    1236 1276   W ActivityManager:    at com.android.server.am.ActivityManagerService.killAppAtUsersRequest(ActivityManagerService.java:12434)
06-27 07:14:46.211    1236 1276   W ActivityManager:    at com.android.server.am.AppNotRespondingDialog$1.handleMessage(AppNotRespondingDialog.java:114)
06-27 07:14:46.211    1236 1276   W ActivityManager:    at android.os.Handler.dispatchMessage(Handler.java:102)
06-27 07:14:46.211    1236 1276   W ActivityManager:    at android.os.Looper.loop(Looper.java:148)
06-27 07:14:46.211    1236 1276   W ActivityManager:    at android.os.HandlerThread.run(HandlerThread.java:61)
06-27 07:14:46.211    1236 1276   W ActivityManager:    at com.android.server.ServiceThread.run(ServiceThread.java:46)

//Step 6. AMS.startProcessLocked()
06-27 07:14:46.211    1236 1276  D ActivityManager: cleanUpApplicationRecord -- 13930
06-27 07:14:46.211    1236 1277   I libprocessgroup: Killing pid 14312 in uid 10227 as part of process group 13930

//Step 7. AS.removeHistoryRecordsForAppLocked()
06-27 07:14:46.216    1236 1276   W ActivityManager: Force removing ActivityRecord{909d520 u0 com.dailyyoga.cn/.FrameworkActivity t1861}: app died, no saved state

//论证Step6的正确性
06-27 07:14:46.230 1236 1276 [null] I ActivityManager: Start proc 14895:com.dailyyoga.cn/u0a227 for activity com.dailyyoga.cn/.FrameworkActivity

接下来，基于上述的日志从源码中找到相应的方法，推测代码执行流。要理解该问题需熟练掌握进程创建流程、Activity启动流程、ANR执行流程。

Step 1. ANR

从核心日志，可以看到com.dailyyoga.cn发生了一次ANR，网上一搜得知这个App是每日瑜伽。该App在界面PlanDetailActivity时，超过5s主线程没有响应input事件, 从而引发应用ANR。由于发生的是前台ANR, 则会弹出对话框, 让用户选择是等待还是关闭该应用。

作为一个App是否有可能导致系统重启，这个还不确定，至少有一点可以推测出，那就是系统重启跟ANR对话框有一定的关系。

Step 2. AS.finishTopRunningActivityLocked

发生ANR后间隔2s就出现上面这行log, 可定位已执行到如下方法，这个方法是由finishTopRunningActivityLocked()调用的。

finishTopRunningActivityLocked

Step 3. AS.startPausingLocked

finishTopRunningActivityLocked

每日瑜伽应用发生异常后, 这时会设置mPausingActivity = null, 这个很重要, 前面传递的参数resuming=false, 则便会走到如下流程

finishTopRunningActivityLocked

Step 4. AS.resumeTopActivityInnerLocked

finishTopRunningActivityLocked

虽然这里没有出现调用栈, 不难看出, 这里发生异常的地方, 应该是next.app.thread.scheduleResumeActivity.之后开始执行startSpecificActivityLocked操作.

Step 5. ASS.startSpecificActivityLocked

finishTopRunningActivityLocked

进入startSpecificActivityLocked方法, 执行realStartActivityLocked()出现Exception, 这里是关键,正常情况直接返回了. 这里发生异常, 那么会执行重新创建进程的操作.

Step 6. AMS.startProcessLocked

紧接着, 看到cleanUpApplicationRecord的log, 反推调用情况有多种, 结合上面输出的libprocessgroup log, 逐一排除, 可以发现程序执行到startProcessLocked()的如下流程:

finishTopRunningActivityLocked

app.pid>0 导致需要杀旧的进程组, 以及清理进程相关信息.

  • startProcessLocked过程
    • 根据进程名,从mProcessNames查询是否存在该进程.
    • 会先设置app.setPid(0),
    • 当进程创建后执行app.setPid(startResult.pid), 设置进程pid;
  • cleanUpApplicationRecordLocked()
    • 当restart=true, 不会设置改变pid; 重启过程会设置pid=0; (即存在provider处于launching状态),
    • 当restart=false, 且pid>0, 则app.setPid(0);

在AMS.handleAppDiedLocked的过程, 会调用 AMS.cleanUpApplicationRecord, 清理组件信息, 输出上述log.

Step 7. AS.removeHistoryRecordsForAppLocked

finishTopRunningActivityLocked

在前面Step6执行handleAppDiedLocked过程, 先执行cleanUpApplicationRecord, 然后经过层层调用会进入AS.removeHistoryRecordsForAppLocked过程。这里的最后一行removeActivityFromHistoryLocked(r, “appDied”), 则进入Step8。

Step 8. AS.removeActivityFromHistoryLocked

finishTopRunningActivityLocked

再来看看removeTask，则进入Step9。

Step 9. AS.removeTask

finishTopRunningActivityLocked

这便是整个问题最为核心的地方, 直接把每日瑜伽的task, 从ActivityStack的mTaskHistory里面移除.

Step 10. AS.finishTopRunningActivityLocked

执行完removeTask()方法，层层回溯，再回到Step2的finishTopRunningActivityLocked()执行完成。 也就是对应如下代码的第2886行，核心是把task从mTaskHistory中移除。

finishTopRunningActivityLocked

执行完2886行，程序继续往下走。由于com.dailyyoga.cn应用的TASK中有3个activity，则不进入第2891行，直接进入2901行。 由于task从mTaskHistory中移除，此时便出现的数组越界问题。

总结

整个过程出现多次Exception引发的重启问题，这个调用链如下：

finishTopRunningActivityLocked
  finishActivityLocked
    startPausingLocked
      resumeTopActivityInnerLocked
        startSpecificActivityLocked
          startProcessLocked
            handleAppDiedLocked
              cleanUpApplicationRecord
                removeHistoryRecordsForAppLocked
                  removeActivityFromHistoryLocked
                    removeTask
  1. App发生一次ANR, 用户点击确定关闭该App;
  2. AS.finishActivityLocked()过程, 执行activity pause操作, 调用schedulePauseActivity过程发生Exception, 导致触发AS.resumeTopActivityInnerLocked()
  3. AS.resumeTopActivityInnerLocked()过程, 执行resume FrameworkActivity, 调用scheduleResumeActivity()过程发生Exception, 导致触发ASS.startSpecificActivityLocked();
  4. ASS.startSpecificActivityLocked()过程, 执行realStartActivityLocked(), 调用scheduleLaunchActivity过程发生Exception, 导致触发AMS.startProcessLocked();
  5. AMS.startProcessLocked()过程, 由于app.pid>0, 导致需要先杀掉旧的进程组, 以及执行handleAppDiedLocked()流程; 没有执行cleanUpApplicationRecordLocked过程, 往往是死亡回调没有回来.
  6. AMS.handleAppDiedLocked过程, 执行AS.removeTask()流程, 从而导致task从ActivityStack的mTaskHistory里面移除.
  7. 最后回到AS.finishTopRunningActivityLocked过程, 便会出现mTaskHistory的数组越界问题.

三. 解决方案

AS.finishTopRunningActivityLocked()方法的主要功能是结束当前在栈顶正处于运行状态的Activity。 过程会有finishActivityLocked方法，本案例在期间发生多次Exception，需要resume当前发生ANR activity的下一个activity，并该该activity所在的task从mTaskHistory中移除。

结论：当task发生remove时，会减少mTaskHistory中的成员个数，从导致mTaskHistory.get(taskNdx)出现数组越界。

问题关键点：需要resume的activity可能是跟当前activity所归属的应用

  • 当发生ANR的应用如果只有单一activity，那么resume的一定是其他应用的activity；在发生异常的时候，便会移除其他应用的task。而发生ANR的应用的task并没有被移除，只是序号变小，则需重新计算该task所在mTaskHistory的位置序号。
  • 当发生ANR的应用至少有两个activity，那么resume的一定是还是当前app的下一个activity；在发生异常的时候，便会移除当前应用的task。此时要么task所在mTaskHistory的位置序号变小，要么当前task直接被移除了，这取决于该应用示范有多个task。这时还需要再执行finishActivityLocked()，否则有可能出现不断重启发生crash的应用。

不管以上那种情况，只要出现了task被remove的情况，都需要更新计算task所在mTaskHistory的位置序号，才能确保不会出现数组越界。至于是否还需要执行finishActivityLocked，这就取决于是否会引发是否会引发重启crash应用的重启行为。

热门标签
工具命令 Android Android10 framework 稳定性 组件学习 进程间通信 Binder 疑难问题 android 框架问题 系统启动 系统组件 Input系统 系统原理 系统服务 系统调试 Handler PKMS
资源网站