android events log来龙去脉，以及activity stop timeout原理

1. 背景
项目的开发过程中，经常遇到app的卡顿问题，显示问题，在没有现场的情况下，往往需要借助events log定位分析问题。本文从实际项目出发，详细介绍了events log的来龙去脉，以及遇到的activity stop timeout的原理分析。

07-14 14:15:22.199849 943 4111 I wm_stop_activity: [0,48692746,com.android.live.audiobox/com.android.liveaudiobox.home.HomeActivity]
07-14 14:15:33.206605 943 1100 W ActivityTaskManager: Activity stop timeout for ActivityRecord{2e6fe0a u0 com.android.live.audiobox/com.android.liveaudiobox.home.HomeActivity t346}
07-14 14:15:33.206741 943 1100 I ActivityTaskManager: Activity reported stop, but no longer stopping: ActivityRecord{2e6fe0a u0 com.android.live.audiobox/com.android.liveaudiobox.home.HomeActivity t346}

2. 问题分析

遇到上面的log，相信大家会有两点疑问：

1. wm_stop_activity 什么意思？是app 已经onStop了吗？还是马上呼叫app执行onStop方法？
2. activity stop还有timeout，timeout时长是多少呢？

疑问一
通过关键字wm_stop_activity 整个源码搜索，搜索结果如下：

上面的搜索结果非常奇怪，怎么是logtags的文件，不是java文件呢？

继续搜索终于在下面的路径下搜到了java文件：
android\out\soong.intermediates\frameworks\base\services\core\services.core.unboosted\android_common\gen\logtags\frameworks\base\services\core\java\com\android\server\wm\EventLogTags.java

  public static void writeWmStopActivity(int user, int token, String componentName) {
    android.util.EventLog.writeEvent(WM_STOP_ACTIVITY, user, token, componentName);
  }

从文件路径可以看出，这个是编译脚本编译出来的。

/**
 * Request to move an activity to stopped state.
 * @hide
 */
public class StopActivityItem extends ActivityLifecycleItem {

    private static final String TAG = "StopActivityItem";

    private int mConfigChanges;

    @Override
    public void execute(ClientTransactionHandler client, IBinder token,
            PendingTransactionActions pendingActions) {
        Trace.traceBegin(TRACE_TAG_ACTIVITY_MANAGER, "activityStop");
        client.handleStopActivity(token, mConfigChanges, pendingActions,
                true /* finalStateRequest */, "STOP_ACTIVITY_ITEM");
        Trace.traceEnd(TRACE_TAG_ACTIVITY_MANAGER);
    }

    private final Runnable mStopTimeoutRunnable = new Runnable() {
        @Override
        public void run() {
            synchronized (mAtmService.mGlobalLock) {
                Slog.w(TAG, "Activity stop timeout for " + ActivityRecord.this);
                if (isInHistory()) {
                    activityStopped(
                            null /*icicle*/, null /*persistentState*/, null /*description*/);
                }
            }
        }
    };

到这里，疑问一应该比较清楚了，wm_stop_activity 是AMS 打印出来的，这个event log之后，app马上会执行onStop方法，且framework会为stop开启一个11s的timeout计时，如果11s的时间内都没有成功执行onStop方法，会执行activityStopped方法。

疑问二
从google的注释来看，这个timeout 11s是非常合理的，考虑到了app 10s的ANR的情况，多出1s是为了让系统有充足的时间dump anr信息。

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