Activity到底是什么時候顯示到屏幕上的呢？

jiji879 7年前發布 | 18K 次閱讀 Activity Android開發移動開發

這兩天我的包工頭歪龍木·靈魂架構師·王半仙·Yrom 給我派了一個活：統計App冷啟動時間。這個任務看上去不難，但是要求統計出來的時間要準，要 特別準 。

意思就是，我必須要按Activity繪制到屏幕上這個時間節點作為標桿，來進行我的統計工作。畢竟如果是因為視圖處理不當而導致的measure/layout/draw耗時太久，這是不能忍的，需要及時統計到。雖然有點蛋疼，但是這個任務還算有意義，我就深挖一下，把過程分享出來。

注：本文所涉及源碼部分的sdk level為21

onResume真的已經顯示了嗎？

如果你看過官方文檔中的Activity生命指引，你會發現它說的是

Activity在onResume生命周期中已經是可見狀態。

那么我們就去這個onResume中看一看。現在我在Activty的onCreate第一行（ super.onCreate 之前）記錄一個時間點，onResume的最后一行( super.onResume 之后)記錄一個時間點，將兩者的差值記錄下來。

打出來的Log是： I/MainActivity: onCreate -> onResume : 70 。即這個過程花費了70ms。那真的是只用了70ms我的Activity就已經完全顯示了嗎？我們來看兩個官方的衡量點：

通過adb shell的命令

$ adb shell am start -W com.desmond.demo/.MainActivity

Starting: Intent { act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] cmp=com.desmond.demo/.MainActivity }
Status: ok
Activity: com.desmond.demo/.MainActivity
ThisTime: 314
TotalTime: 314
WaitTime: 314
Complete

啟動Activity時的可以看Tag = ActivityManager打出來的Log：

I/ActivityManager: Displayed com.desmond.testapplication/.MainActivity: +314ms

這兩個時間是一樣的，我們看哪個都行。這個314ms的啟動過程和上面的70ms 是同一次啟動過程打出來的日志 ，那么問題來了，怎么會和我打出來的Log時間相差這么大？我們先看看系統打出來的時間到底是什么時間。

打出這段log的代碼在 ActivityRecord ：

//ActivityRecord
privatevoidreportLaunchTimeLocked(finallongcurTime){
    final ActivityStack stack = task.stack;
    if (stack == null) {
        return;
    }
    final long thisTime = curTime - displayStartTime;
    final long totalTime = stack.mLaunchStartTime != 0
            ? (curTime - stack.mLaunchStartTime) : thisTime;
    if (SHOW_ACTIVITY_START_TIME) {
        // ...其他代碼
        StringBuilder sb = service.mStringBuilder;
        sb.setLength(0);
        sb.append("Displayed ");
        sb.append(shortComponentName);
        sb.append(": ");
        TimeUtils.formatDuration(thisTime, sb);
        if (thisTime != totalTime) {
            sb.append(" (total ");
            TimeUtils.formatDuration(totalTime, sb);
            sb.append(")");
        }
        Log.i(TAG, sb.toString());
    }
    // ...其他代碼
}

它的調用時機我們后面再討論，首先看一下它打出了什么。這個函數中將 totalTime 作為Displayed時間打了出來，值為當前時間 - stack.mLaunchStartTime 。那這個mLaunchStartTime是什么時候被記錄的呢？查了一下調用發現在 ActivityStackSupervisor.startSpecificActivityLocked 會調用 stack.setLaunchTime(r) 去設置這個時間。

那么我們可以得出第一個結論：

結論1： 系統打出來的時間包含了進程啟動的時間。

因為進程啟動都是在 ActivityStackSupervisor.startSpecificActivityLocked() 中進行的，以ActivityThread.main為入口啟動一個新進程。

但是進程啟動這么耗時？我的test activiy也沒有自定義Application，更別提什么耗時操作了。我來實踐一下 熱啟動 ，App退出，但是不殺進程，再對比一下我打的log和系統log的時間區別。

我：I/MainActivity: onCrete -> onResume : 37

系統： I/ActivityManager: Displayed com.desmond.testapplication/.MainActivity: +103ms

依然差了很多！

看來我們需要研究一下Activity的onResume過程及系統上報Displayed的時機了。

深入探究onResume過程

我先對AMS觸發Activity的onResume這個過程畫了一張圖：

在ActivityManagerService(AMS)告知Activity要resume時，它通過調用 ApplicationThread.scheduleResumeActivity 給 ActivityThread.H （一個Handler）發送消息 RESUME_ACTIVITY ，然后H開始處理消息：

case RESUME_ACTIVITY:
    Trace.traceBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER, "activityResume");
    handleResumeActivity((IBinder) msg.obj, true, msg.arg1 != 0, true);
    Trace.traceEnd(Trace.TRACE_TAG_ACTIVITY_MANAGER);
    break;

在這個 handleResumeActivity 中就處理了所有的Resume邏輯，我們進去一探究竟。

//ActivityThread.java
finalvoidhandleResumeActivity(IBinder token,
        boolean clearHide, boolean isForward, boolean reallyResume) {
    // 一些其他代碼

    // 這步onResume
    ActivityClientRecord r = performResumeActivity(token, clearHide);

    if (r != null) {
        final Activity a = r.activity;

        // 一些其他代碼

        if (r.window == null && !a.mFinished && willBeVisible) {
            r.window = r.activity.getWindow();
            View decor = r.window.getDecorView();
            decor.setVisibility(View.INVISIBLE);
            ViewManager wm = a.getWindowManager();
            WindowManager.LayoutParams l = r.window.getAttributes();
            a.mDecor = decor;
            l.type = WindowManager.LayoutParams.TYPE_BASE_APPLICATION;
            l.softInputMode |= forwardBit;
            if (a.mVisibleFromClient) {
                a.mWindowAdded = true;
                wm.addView(decor, l); //這步很關鍵
            }
        }
        //...
    }
}

Activity.onResume() 這一步就是在 performResumeActivity 里面調用的，有興趣的同學可以去看看，里面代碼很簡單。

為什么說 wm.addView 這一步很關鍵？真正對Activity的視圖進行計算、繪制、flush到window上是 wm.addWindow 這一步做的，這里面代碼比較多，我直接畫張圖看清晰一點：

這張圖的代碼就不放了，關鍵的類和方法都在里面，有興趣的同學可以自行翻閱。有幾個注意的點：

Activity#getWindowManager() 拿到的是Activity的成員變量 mWindowManager ，它是一個 WindowManagerIpml 實例，在 Activity.attach 內被賦值。所以我們在第一步直接就跳轉到了 WindowManagerImpl.addView()
ViewRootImpl 在requestLayout的時候將一個Runnable交由 Choreographer 去調度，讓它能夠在下一個繪制幀時執行它。這個Runnable內只有一條語句，就是執行 doTraversal ，主要的內容在其中執行的 performTraversal 中，這個函數非常非常長，做的事情大致就是從頂至下的measure/layout/draw，通知 ViewTreeObserver 的各類Listener也大部分都是在這一步中完成的。

這時候我們回頭看之前 ActivityThread.handleResumeActivity 的代碼： Activity的onResume在wm.addView之前！ 。因為View的計算、繪制等都在wm.addView之后執行，那我們可以得出第二個結論：

結論2：在onResume的時候是肯定統計不到View的measure/layout/draw時間的。

這時候我們要搞清楚的是，上面系統的Log是在哪一步調用的，它是否包含了View的measure/layout/draw的時間？這個過程可是一頓好找，大概是如下圖所示流程：

5-6步之間被我精簡了一小部分內容，我來簡單解釋一下這個過程：

ViewRootImpl在 performTraversals() 的最后會調用 performDraw() 來將內容繪制到Surface上，最后一步它會執行 mWindowSession.finishDrawing 。這個 mWindowSession 是一個Session對象，它維持著ViewRootImpl與WindowManagerService(WMS)之間的聯系。
在這之后WMS通過Handler來調度繪制Surface的任務，它給自己內部類H發送了一個 DO_TRAVERSAL 消息。收到消息之后它就會執行 performLayoutAndPlaceSurfacesLocked 函數，之后有一系列的鏈式調用由于方法名字太長并且于本文沒有太多用處，在我的圖里被省略了。最后它會走到 performLayoutAndPlaceSurfacesLockedInner ，這里面會將Surface繪制到屏幕上，并調用 handleAppTransitionReadyLocked ，并如圖所示繼續向后調用。
ActivityRecord.Token是一個Binder對象，它活在ActivityManagerService進程中，用于AMS與WMS之間的通信。相對應的，AppWindowToken活在WindowManagerService進程中。每一個ActivityRecord.Token都對應一個AppWindowToken。

那我們可以確定的是，在看到系統這條日志時，View的計算、繪制已經完成，并且Surface也被繪制到屏幕上。這樣我們可以得出第三個結論：

結論3：系統打出來的日志時Activity已經被完全展示到了屏幕上。

View繪制結束的回調時機

得出了結論，那我們要怎么知道什么時候View繪制結束呢？這里就仁者見仁，智者見智了。

首先可以確認的是，所有ViewTreeObserver里面的Listener都是不夠準確的。為什么呢？它們里面能統計到的最遲就是 OnDrawListener ，我們可以在 ViewRootImpl#draw() 函數中看到，它是在真正draw這一步之前調用的，也就是說它沒有統計到draw的時間。

我提供一個思路，能夠準確獲取到包括View的measure/layout/draw過程的時間。那就是在 onResume 中添加一個 IdleHandler ：

@Override
protectedvoidonResume(){
    super.onResume();
    Looper.myQueue().addIdleHandler(new MessageQueue.IdleHandler() {
        @Override
        publicbooleanqueueIdle(){
            Log.i(TAG, "onCreate -> idle : " + (SystemClock.uptimeMillis() - time));
            return false;
        }
    });
}

這個IdleHandler是什么？它會在Looper的消息隊列處理完當前阻塞的消息（即Idle中，等待獲取下一條消息）時被調用。我這里直接指定了主線程的消息隊列，那我在 onResume 中給它加入一個IdleHandler，它會什么時候調用呢，我們回顧一下Activity的onResume->ViewRoot的traversal這個過程，我做了一些修改：

這里有一個需要注意的地方：

ViewRootImpl在向Choreographer發送調度消息時，特地向主線程的Looper消息循環發送了一個“障礙消息”。利用 MessageQueue#postSyncBarrier 可以做到這一點，當出現了這一個障礙消息的時候，消息循環就暫時無法處理后續排入消息。有興趣的同學可以自行研究這個過程。

Choreographer通過直接在native操作主進程的MessageQueue來排入消息，從而它的執行會無視我們加入的“障礙消息”。即 ViewRootImpl#doTraversal 這個函數也是在一次消息處理中發生的。它此時移除了MessageQueue里面的障礙消息，并且執行performTraversals。

需要注意的是： 這整個過程都是在主線程的消息循環中發生的。 這個過程可以描述為如下幾步：

ActivityThread.H在處理 RESUME_ACTIVITY 消息時調用的 handleResumeActivity 會觸發 Activity#onResume 與 ViewRootImpl#doTraversal 。
ViewRootImpl#doTraversal 向主進程Looper發送了一個“障礙消息”，使主進程Looper無法繼續處理后續消息。
Choreographer通過native向主進程Looper排入消息，移除“障礙消息”，并執行 ViewRootImpl#doTraversal 。

所以如果我們在onResume中向主進程添加入一個IdleHandler，它是必然會在這三步都走完，主進程Looper的MessageQueue才可能觸發Idle狀態，并觸發IdleHandler回調。

我們可以實驗一下：在添加入的IdleHandler內打點，計算與onCreate第一行打點時間之差，最后打出來的Log：

MainActivity: onCrete -> onResume : 12
MainActivity: onCrete -> onPreDraw : 138
MainActivity: onCrete -> onPreDraw : 147
MainActivity: onCrete -> idleHandler : 166
ActivityManager: Displayed com.desmond.testapplication/.MainActivity: +192ms

雖然還是離ActivityManager打出來的差了一點，但是這也是有理由的。我們看上面的WMS繪制Surface那一步，是通過Handler發送異步消息完成的，這里統計不到。

總結

雖然沒有完全貼近系統打出來的日志，但是通過IdleHandler的方式已經能統計到我想要的內容了（由Activity的onCreate第一步到整個界面顯示）。

來自：http://blog.desmondyao.com/android-show-time/

本文由用戶 jiji879 自行上傳分享，僅供網友學習交流。所有權歸原作者，若您的權利被侵害，請聯系管理員。

轉載本站原創文章，請注明出處，并保留原始鏈接、圖片水印。

本站是一個以用戶分享為主的開源技術平臺，歡迎各類分享！

本文地址：http://www.baiduhome.net/lib/view/open1484207641185.html

Activity Android開發移動開發

Activity到底是什么時候顯示到屏幕上的呢？

onResume真的已經顯示了嗎？

深入探究onResume過程

View繪制結束的回調時機

總結

相關經驗

相關資訊

相關文檔

目錄