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

這兩天我的包工頭歪龍木·靈魂架構師·王半仙·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的命令

? 1 2 3 4 5 6 7 8 9

? $ 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：

? 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26

? //ActivityRecord private void reportLaunchTimeLocked(final long curTime) { 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為入口啟動一個新進程。如果對于這里不明白，可以參考一下老羅的Android應用程序啟動過程源代碼分析。

但是進程啟動這么耗時？我的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開始處理消息：

? 1 2 3 4 5

? 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邏輯，我們進去一探究竟。

? 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30

? //ActivityThread.java final void handleResumeActivity(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)之間的聯系。（ViewRootImpl與WMS通信部分可以參考老羅的Android應用程序窗口（Activity）與WindowManagerService服務的連接過程分析)

在這之后WMS通過Handler來調度繪制Surface的任務，它給自己內部類H發送了一個DO_TRAVERSAL消息。收到消息之后它就會執行performLayoutAndPlaceSurfacesLocked函數，之后有一系列的鏈式調用由于方法名字太長并且于本文沒有太多用處，在我的圖里被省略了。最后它會走到performLayoutAndPlaceSurfacesLockedInner，這里面會將Surface繪制到屏幕上，并調用handleAppTransitionReadyLocked，并如圖所示繼續向后調用。

ActivityRecord.Token是一個Binder對象，它活在ActivityManagerService進程中，用于AMS與WMS之間的通信。相對應的，AppWindowToken活在WindowManagerService進程中。每一個ActivityRecord.Token都對應一個AppWindowToken。它們的連接建立可以參考上面說到的老羅文章，以及我的另一篇文章：一個詭異的BadTokenException。

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

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

View繪制結束的回調時機

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

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

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

? 1 2 3 4 5 6 7 8 9 10 11

? @Override protected void onResume() { super.onResume(); Looper.myQueue().addIdleHandler(new MessageQueue.IdleHandler() { @Override public boolean queueIdle() { 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來排入消息，從而它的執行會無視我們加入的“障礙消息”。（這部分代碼就不深入了，可以參考老羅的Android應用程序消息處理機制（Looper、Handler）分析）。即ViewRootImpl#doTraversal這個函數也是在一次消息處理中發生的。它此時移除了MessageQueue里面的障礙消息，并且執行performTraversals。

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

ActivityThread.H在處理RESUME_ACTIVITY消息時調用的handleResumeActivity會觸發Activity#onResume與ViewRootImpl#doTraversal。

ViewRootImpl#scheduleTraversals向主進程Looper發送了一個“障礙消息”，使主進程Looper無法繼續處理后續消息。

Choreographer通過native向主進程Looper排入消息，移除“障礙消息”，并執行ViewRootImpl#doTraversal。

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

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

? 1 2 3 4 5

? 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第一步到整個界面顯示）。

老羅的博客和AOSP源碼都是很棒的參考資料，建議多看看Handler/Looper的消息循環機制、AMS/WMS/主進程之間的交互，才能比較好的理解這個過程。

參考文章：

• Android性能優化典范(第6季)
• Android應用程序消息處理機制（Looper、Handler）分析
• Android應用程序窗口（Activity）與WindowManagerService服務的連接過程分析

總結

以上是生活随笔為你收集整理的Android性能优化之较精确的获取图像显示到屏幕上的时间的全部內容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網站內容還不錯，歡迎將生活随笔推薦給好友。