腾讯性能监控框架Matrix源码分析（十一）TracePlugin 之StartupTracer启动耗时分析

说到启动耗时，首先知道几个概念

App三种启动方式：

官方定义了三种启动方式：

• 冷启动：彻底杀死应用进程后启动APP的方式。系统会为应用创建进程、主线程，执行Application、launch Activity的初始化方法。

• 热启动：没有杀死应用进程情况下启动APP的方式，比如应用切到后台。热启动中，系统的所有工作就是将您的 Activity 带到前台。这种情况不会执行Application的初始化方法，如果应用的所有 Activity 都还驻留在内存中，则应用可以无须重复对象初始化、布局inflate和呈现。

• 温启动：

  • 有两种常见场景：

    • 点击回退键方式退出应用
    • 应用在后台被系统回收

  • 启动逻辑介于冷启动和热启动之间。如果是回退键方式退出应用再重启，不会执行Application初始化，但是需要初始化Activity。如果是系统回收后的重启，Application和Activity都会初始化，但是可以通过savedInstanceState拿到退出前Activity的状态。

三种启动方式中，我们这里只对冷启动做分析。启动Demo后，可以看到如下log：

Matrix.StartupTracer: [report] applicationCost:42 firstScreenCost:244 allCost:2306 isWarmStartUp:false

log显示是冷启动(isWarmStartUp:false)方式，Application初始化耗时(applicationCost) 42ms，首屏耗时(firstScreenCost) 244ms，总耗时(allCost) 2306ms。通过log可以知道是StartupTracer做的上报。

StartupTracer给各个耗时统计点提供了注释：

简单解释下上图中几个关键统计点：

• Application初始化耗时(applicationCost)：

  • 起始点对应Application.onCreate()，由ActivityThreadHacker.sApplicationCreateBeginTime字段记录起始点时间戳，该字段在ActivityThreadHacker.hackSysHandlerCallback()赋值。
  • 结束点比较有意思，matrix是通过hook ActivityThread的mH.mCallback实现拦截主线程message，Application和Activity的初始化任务都是通过主线程Handler机制调度的。当接收到launch activity调度message时认为Application初始化完成，以此作为结束点。结束点由ActivityThreadHacker.sApplicationCreateEndTime字段记录其时间戳，该字段在ActivityThreadHacker.HackCallback.handleMessage()中赋值。

• 首屏耗时(firstScreenCost)：

  • 指app启动到第一个Activity(launch activity)初始化完成的耗时，可以认为包含了applicationCost + launch activity的初始化耗时。
  • 起始点和applicationCost的起始点一样，由ActivityThreadHacker.sApplicationCreateBeginTime字段记录时间戳。
  • 结束点对应launch activity的onWindowFocusChange()，在StartupTracer.onActivityFocused()中标记。Activity.onWindowFocusChange()执行时，认为Activity对用户可见。

• 冷启动耗时(coldCost)

  • app启动到第一个对用户有意义的Activity（对应图中的careActivity）初始化完成耗时。
  • 应用一般仅在闪屏页即launch activity做logo展示、应用初始化的工作，其后的第一个Activity做为主页Activity，这个Activity就是careActivity。所以把careActivity的初始化完成做为coldCost的结束点。

• 温启动耗时(warmCost)

  • 因为Application不会重新初始化，所以只统计Activity的初始化耗时，和firstActivity含义一致。
  • 起始点是launchActivity初始化的开始点。
  • 结束点是launchActivity onWindfocusChanged()执行点。

上面解释了几个耗时节点的概念，接下来分别看看具体的实现逻辑。

之前插件在编译器为 Activity#onWindowFocusChanged 织入 AppMethodBeat.at 方法，这样可以获取每个 Activity 的 onWindowFocusChanged 回调时间。

为什么是onWindowFocusChanged？ 因为该生命周期在onResume之后，回调是否获取焦点的参数，这个时候拿到焦点基本视图已经渲染完了

然后在第一个 AppMethodBeat.i 方法调用时，记录此时的时间作为进程 zygote 后的时间；hook ActivityThread 中的 mH 中的 Callback ，通过检查第一个 Activity 或 Service 或 Receiver 的 what，以此时的时间作为 Application 创建结束时间，该时间与上面的时间之差记为 Application创建耗时 。
在第一个 Activity 的 onWindowFocusChange 回调时，此时的时间减去 zygote 时间即为 首屏启动耗时 ；
第二个 Activity 的 onWindowFocusChange 回调时，时间减去 zygote 的时间即为 整个冷启动的时间。

当一个APP冷启动后对于Java层一定会先走Application的创建attatchBase方法，这个函数可以视为app启动的开始节点，所以这里插桩了AppMethBeat.i方法，我们进入该方法看看 matrix/matrix-android/matrix-trace-canary/src/main/java/com/tencent/matrix/trace/core/AppMethodBeat.java

public static void i(int methodId) {

    if (status <= STATUS_STOPPED) {
        return;
    }
    if (methodId >= METHOD_ID_MAX) {
        return;
    }

    if (status == STATUS_DEFAULT) {
        synchronized (statusLock) {
            if (status == STATUS_DEFAULT) {
                realExecute();
                status = STATUS_READY;
            }
        }
    }
    ...
}

status默认状态是STATUS_DEFAULT，因此第一次执行AppMethodBeat#i方法肯定会执行到realExecute()方法，这里面相当于就是初始化AppMethodBeat以及执行其他的一些操作了。

private static void realExecute() {
    MatrixLog.i(TAG, "[realExecute] timestamp:%s", System.currentTimeMillis());

    sCurrentDiffTime = SystemClock.uptimeMillis() - sDiffTime;

    sHandler.removeCallbacksAndMessages(null);
    sHandler.postDelayed(sUpdateDiffTimeRunnable, Constants.TIME_UPDATE_CYCLE_MS);
    sHandler.postDelayed(checkStartExpiredRunnable = new Runnable() {
        @Override
        public void run() {
            synchronized (statusLock) {
                MatrixLog.i(TAG, "[startExpired] timestamp:%s status:%s", System.currentTimeMillis(), status);
                if (status == STATUS_DEFAULT || status == STATUS_READY) {
                    status = STATUS_EXPIRED_START;
                }
            }
        }
    }, Constants.DEFAULT_RELEASE_BUFFER_DELAY);

    // hook mH，为StartUpTracer提供支持
    ActivityThreadHacker.hackSysHandlerCallback();
    LooperMonitor.register(looperMonitorListener);
}

我们关注一下ActivityThreadHacker.hackSysHandlerCallback()这个方法，这里面 hook 了 mH 的 mCallback，这样可以 Application 初始化结束的时间。 matrix/matrix-android/matrix-trace-canary/src/main/java/com/tencent/matrix/trace/hacker/ActivityThreadHacker.java

public class ActivityThreadHacker {
    private static final String TAG = "Matrix.ActivityThreadHacker";
    // 进程启动的时间
    private static long sApplicationCreateBeginTime = 0L;
    // 四大组件首次执行到的时间
    private static long sApplicationCreateEndTime = 0L;
    // Activity最后一次launch的时间
    private static long sLastLaunchActivityTime = 0L;
    public static AppMethodBeat.IndexRecord sLastLaunchActivityMethodIndex = new AppMethodBeat.IndexRecord();
    public static AppMethodBeat.IndexRecord sApplicationCreateBeginMethodIndex = new AppMethodBeat.IndexRecord();
    public static int sApplicationCreateScene = -100;

    public static void hackSysHandlerCallback() {
        try {
            //hack只会走一次，这里便是app启动的时间戳
            sApplicationCreateBeginTime = SystemClock.uptimeMillis();
            //打入标记，方便后序根据阶段去筛查函数耗时
            sApplicationCreateBeginMethodIndex = AppMethodBeat.getInstance().maskIndex("ApplicationCreateBeginMethodIndex");
            Class<?> forName = Class.forName("android.app.ActivityThread");
            Field field = forName.getDeclaredField("sCurrentActivityThread");
            field.setAccessible(true);
            Object activityThreadValue = field.get(forName);
            Field mH = forName.getDeclaredField("mH");
            mH.setAccessible(true);
            Object handler = mH.get(activityThreadValue);
            Class<?> handlerClass = handler.getClass().getSuperclass();
            Field callbackField = handlerClass.getDeclaredField("mCallback");
            callbackField.setAccessible(true);
            Handler.Callback originalCallback = (Handler.Callback) callbackField.get(handler);
            HackCallback callback = new HackCallback(originalCallback);
            callbackField.set(handler, callback);
            MatrixLog.i(TAG, "hook system handler completed. start:%s SDK_INT:%s", sApplicationCreateBeginTime, Build.VERSION.SDK_INT);
        } catch (Exception e) {
            MatrixLog.e(TAG, "hook system handler err! %s", e.getCause().toString());
        }
    }

    public static long getApplicationCost() {
        return ActivityThreadHacker.sApplicationCreateEndTime - ActivityThreadHacker.sApplicationCreateBeginTime;
    }

    public static long getEggBrokenTime() {
        return ActivityThreadHacker.sApplicationCreateBeginTime;
    }

    public static long getLastLaunchActivityTime() {
        return ActivityThreadHacker.sLastLaunchActivityTime;
    }


    private final static class HackCallback implements Handler.Callback {
        private static final int LAUNCH_ACTIVITY = 100;
        private static final int CREATE_SERVICE = 114;
        private static final int RECEIVER = 113;
        public static final int EXECUTE_TRANSACTION = 159; // for Android 9.0
        private static boolean isCreated = false;
        private static int hasPrint = 10;

        private final Handler.Callback mOriginalCallback;

        HackCallback(Handler.Callback callback) {
            this.mOriginalCallback = callback;
        }

        @Override
        public boolean handleMessage(Message msg) {
            //开关，是否记录耗时，不记录还保持原来逻辑
            if (!AppMethodBeat.isRealTrace()) {
                return null != mOriginalCallback && mOriginalCallback.handleMessage(msg);
            }
            //是否是启动的app,即清单文件配置为<category android:name="android.intent.category.LAUNCHER" />的activity 
            boolean isLaunchActivity = isLaunchActivity(msg);
            //日志，忽略
            if (hasPrint > 0) {
                MatrixLog.i(TAG, "[handleMessage] msg.what:%s begin:%s isLaunchActivity:%s", msg.what, SystemClock.uptimeMillis(), isLaunchActivity);
                hasPrint--;
            }
            //记录启动Activity的时间和打入启动的函数标记，方便后序根据阶段去筛查函数耗时
            if (isLaunchActivity) {
                ActivityThreadHacker.sLastLaunchActivityTime = SystemClock.uptimeMillis();
                ActivityThreadHacker.sLastLaunchActivityMethodIndex = AppMethodBeat.getInstance().maskIndex("LastLaunchActivityMethodIndex");
            }
            //创建只走一次，去重标记
            if (!isCreated) {
                //当进入启动页或者其他Service Receiver组件表示Application已经执行完毕
                if (isLaunchActivity || msg.what == CREATE_SERVICE || msg.what == RECEIVER) { 
                    //正好记录下结束时间戳
                    ActivityThreadHacker.sApplicationCreateEndTime = SystemClock.uptimeMillis();
                    ActivityThreadHacker.sApplicationCreateScene = msg.what;
                    //打上标记，防止重复进入
                    isCreated = true;
                }
            }
            //回调原生的handleMessage
            return null != mOriginalCallback && mOriginalCallback.handleMessage(msg);
        }

        private Method method = null;

       
}

hook的目的在于接管handler的handleMessage,跟着我的代码注释可以屡一下逻辑，核心就是记录application的启动到结束时间戳，并在关键节点打入函数标记maskIndex，方便后序去根据节点筛查函数。

为什么要hook ActivityThread 中的 mH 中的 Callback？

了解安卓启动流程的都知道。三大组件activity service receiver一定会走到ActivityThread内的handlermessage来处理真正的组件启动动作，除了Provider其他任何一个组件开始执行表示application已经执行完了，所以这里可以记录application end的时间。

isLaunchActivity那怎么判断一个消息是launch activity的消息呢？

private boolean isLaunchActivity(Message msg) {
            //Android9.0引入了ClientTransaction辅助管理应用和页面的生命周期。
            //Application初始化时，AMS通过`ActivityThread.ApplicationThread`向
            //ActivityThread.mH`发送一个what为`EXECUTE_TRANSACTION`，obj为
            //ClientTransaction`的消息，且该消息中的ClientTransaction带有一个
            //LaunchActivityItem的Callback。
            if (Build.VERSION.SDK_INT > Build.VERSION_CODES.O_MR1) {
                if (msg.what == EXECUTE_TRANSACTION && msg.obj != null) {
                    try {
                        if (null == method) {
                            Class clazz = Class.forName("android.app.servertransaction.ClientTransaction");
                            method = clazz.getDeclaredMethod("getCallbacks");
                            method.setAccessible(true);
                        }
                        List list = (List) method.invoke(msg.obj);
                        if (!list.isEmpty()) {
                            return list.get(0).getClass().getName().endsWith(".LaunchActivityItem");
                        }
                    } catch (Exception e) {
                        MatrixLog.e(TAG, "[isLaunchActivity] %s", e);
                    }
                }
                return msg.what == LAUNCH_ACTIVITY;
            } else {
                return msg.what == LAUNCH_ACTIVITY;
            }
        }
    } 
 }   

Android9.0引入了ClientTransaction辅助管理应用和页面的生命周期。Application初始化时，AMS通过ActivityThread.ApplicationThread向ActivityThread.mH发送一个what为EXECUTE_TRANSACTION，obj为ClientTransaction的消息，且该消息中的ClientTransaction带有一个LaunchActivityItem的Callback。

所以上面isLaunchActivity()就是通过这个思路检测launch activity的，发现符合条件的主线程消息，且消息的第一个callback类名以LaunchActivityItem为结尾，即认为发起launch activity初始化流程。低版本则更简单，直接看what标记。

在计算出Application初始化的起始时间点后，我们继续看看StartUpTracer#onActivityFocused里面的代码：

matrix/matrix/matrix-android/matrix-trace-canary/src/main/java/com/tencent/matrix/trace/tracer/StartupTracer.java

@Override
public void onActivityFocused(String activity) {
    // 若coldCost为初始值0，则说明这段代码从来没有运行过，那么认为是冷启动
    if (isColdStartup()) {
        // 若firstScreenCost为初始值0，则说明这是第一个获取焦点的Activity，记录时间差为首屏启动耗时
        if (firstScreenCost == 0) {
            //EggBrokenTime就是 sApplicationCreateBeginTime的时间
            this.firstScreenCost = uptimeMillis() - ActivityThreadHacker.getEggBrokenTime();
        }
        // 若已经展示过了首屏Activity，则此Activity是真正的MainActivity，记录此时时间差为冷启动耗时，大部分app都会有个广告页，这里专门做了适配，广告页以初始化手动配置来识别
        if (hasShowSplashActivity) {
             //EggBrokenTime就是 sApplicationCreateBeginTime的时间
             //走过广告的下一个页面那就是真正的启动全部结束的时间
            coldCost = uptimeMillis() - ActivityThreadHacker.getEggBrokenTime();
        } else {
            // 若还没有展示过首屏Activity splashActivities初始化手动配置的，这是splash
            if (splashActivities.contains(activity)) {
                // 且声明的首屏Activity列表中包含此Activity，则设置标志位
                hasShowSplashActivity = true;
            } else if (splashActivities.isEmpty()) {
                // 声明的首屏Activity列表为空，则整个冷启动耗时就为首屏启动耗时
                MatrixLog.i(TAG, "default splash activity[%s]", activity);
                coldCost = firstScreenCost;
            } else {
                MatrixLog.w(TAG, "pass this activity[%s] at duration of start up! splashActivities=%s", activity, splashActivities);
            }
        }
        // 分析冷启动耗时
        if (coldCost > 0) {
            analyse(ActivityThreadHacker.getApplicationCost(), firstScreenCost, coldCost, false);
        }

    } else if (isWarmStartUp()) {
        // 是否是温启动，这里isWarmStartUp标志位还依赖于监听ActivityLifecycleCallbacks，这里代码没有贴出来
        // 温启动时间是当前时间减去最后一次 launch Activity 的时间
        isWarmStartUp = false;
        long warmCost = uptimeMillis() - ActivityThreadHacker.getLastLaunchActivityTime();
        if (warmCost > 0) {
            analyse(ActivityThreadHacker.getApplicationCost(), firstScreenCost, warmCost, true);
        }
    }

}

//一旦启动后coldCost会成为固定值，所以没有设置就是冷启动。
private boolean isColdStartup() {
    return coldCost == 0;
}
//是否热启通过变量控制
private boolean isWarmStartUp() {
    return isWarmStartUp;
}

总结：

• Application初始化耗时(applicationCost)：

  • 统计Application.onCreate()到ActivityThread.mH接收LaunchActivityItem消息这段过程的时间

• 首屏耗时(firstScreenCost)：

  • 指app启动到闪屏页Activity(launch activity)初始化完成的耗时，可以认为包含了applicationCost + launch activity页面的初始化耗时

• 冷启动耗时(coldCost)

  • app启动(Application.onCreate())到第一个对用户有意义的Activity（careActivity）初始化完成(Activity.onWindowFocusChanged())的耗时

无论是冷启动还是温启动，都需要分析这些数据，然后上报：我们进入analse方法

private void analyse(long applicationCost, long firstScreenCost, long allCost, boolean isWarmStartUp) {
    MatrixLog.i(TAG, "[report] applicationCost:%s firstScreenCost:%s allCost:%s isWarmStartUp:%s", applicationCost, firstScreenCost, allCost, isWarmStartUp);
    long[] data = new long[0];
    // 冷启动不得超过 10s
    if (!isWarmStartUp && allCost >= coldStartupThresholdMs) { // for cold startup
        // 分析 ApplicationCreateBeginMethodIndex 的方法栈
        data = AppMethodBeat.getInstance().copyData(ActivityThreadHacker.sApplicationCreateBeginMethodIndex);
        ActivityThreadHacker.sApplicationCreateBeginMethodIndex.release();

    }
    // 温启动不得超过 4s
    else if (isWarmStartUp && allCost >= warmStartupThresholdMs) {
        // 分析 LastLaunchActivityMethodIndex 的方法栈
        data = AppMethodBeat.getInstance().copyData(ActivityThreadHacker.sLastLaunchActivityMethodIndex);
        ActivityThreadHacker.sLastLaunchActivityMethodIndex.release();
    }

    MatrixHandlerThread.getDefaultHandler().post(new AnalyseTask(data, applicationCost, firstScreenCost, allCost, isWarmStartUp, ActivityThreadHacker.sApplicationCreateScene));

}

@Override
public void run() {
    LinkedList<MethodItem> stack = new LinkedList();
    if (data.length > 0) {
        TraceDataUtils.structuredDataToStack(data, stack, false, -1);
        TraceDataUtils.trimStack(stack, Constants.TARGET_EVIL_METHOD_STACK, new TraceDataUtils.IStructuredDataFilter() {
            @Override
            public boolean isFilter(long during, int filterCount) {
                return during < filterCount * Constants.TIME_UPDATE_CYCLE_MS;
            }

            @Override
            public int getFilterMaxCount() {
                return Constants.FILTER_STACK_MAX_COUNT;
            }

            @Override
            public void fallback(List<MethodItem> stack, int size) {
                MatrixLog.w(TAG, "[fallback] size:%s targetSize:%s stack:%s", size, Constants.TARGET_EVIL_METHOD_STACK, stack);
                Iterator iterator = stack.listIterator(Math.min(size, Constants.TARGET_EVIL_METHOD_STACK));
                while (iterator.hasNext()) {
                    iterator.next();
                    iterator.remove();
                }

            }
        });
    }

    StringBuilder reportBuilder = new StringBuilder();
    StringBuilder logcatBuilder = new StringBuilder();
    long stackCost = Math.max(allCost, TraceDataUtils.stackToString(stack, reportBuilder, logcatBuilder));
    String stackKey = TraceDataUtils.getTreeKey(stack, stackCost);

    // for logcat
    if ((allCost > coldStartupThresholdMs && !isWarmStartUp)
            || (allCost > warmStartupThresholdMs && isWarmStartUp)) {
        MatrixLog.w(TAG, "stackKey:%s \n%s", stackKey, logcatBuilder.toString());
    }

    // report
    report(applicationCost, firstScreenCost, reportBuilder, stackKey, stackCost, isWarmStartUp, scene);
}

之前AppMethodBeat的文章已经分析过了，下面就是对存储的函数long数组转换出函数方法，并进行数量时间的裁剪，最终根据情况来决定是否上报。

讲了几章函数耗时处理，我们只知道数据从哪来，那么源头是如何侵入代码呢？下一章带你熟悉插桩技术。