Android效能優化之較精確的獲取影象顯示到螢幕上的時間
轉載自：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/主程序之間的互動，才能比較好的理解這個過程。
參考文章：