轉(zhuǎn)載自：http://blog.desmondyao.com/android-show-time/

這兩天我的包工頭歪龍木·靈魂架構(gòu)師·王半仙·Yrom給我派了一個(gè)活：統(tǒng)計(jì)App冷啟動(dòng)時(shí)間。這個(gè)任務(wù)看上去不難，但是要求統(tǒng)計(jì)出來(lái)的時(shí)間要準(zhǔn)，要特別準(zhǔn)。

意思就是，我必須要按Activity繪制到屏幕上這個(gè)時(shí)間節(jié)點(diǎn)作為標(biāo)桿，來(lái)進(jìn)行我的統(tǒng)計(jì)工作。畢竟如果是因?yàn)橐晥D處理不當(dāng)而導(dǎo)致的measure/layout/draw耗時(shí)太久，這是不能忍的，需要及時(shí)統(tǒng)計(jì)到。雖然有點(diǎn)蛋疼，但是這個(gè)任務(wù)還算有意義，我就深挖一下，把過(guò)程分享出來(lái)。

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

onResume真的已經(jīng)顯示了嗎？

如果你看過(guò)官方文檔中的Activity生命指引，你會(huì)發(fā)現(xiàn)它說(shuō)的是

Activity在onResume生命周期中已經(jīng)是可見(jiàn)狀態(tài)。

那么我們就去這個(gè)onResume中看一看。現(xiàn)在我在Activty的onCreate第一行（super.onCreate之前）記錄一個(gè)時(shí)間點(diǎn)，onResume的最后一行(super.onResume之后)記錄一個(gè)時(shí)間點(diǎn)，將兩者的差值記錄下來(lái)。

打出來(lái)的Log是：I/MainActivity: onCreate -> onResume : 70。 即這個(gè)過(guò)程花費(fèi)了70ms。那真的是只用了70ms我的Activity就已經(jīng)完全顯示了嗎？我們來(lái)看兩個(gè)官方的衡量點(diǎn)：

• 通過(guò)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

• 啟動(dòng)Activity時(shí)的可以看Tag = ActivityManager打出來(lái)的Log：

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

這兩個(gè)時(shí)間是一樣的，我們看哪個(gè)都行。這個(gè)314ms的啟動(dòng)過(guò)程和上面的70ms是同一次啟動(dòng)過(guò)程打出來(lái)的日志，那么問(wèn)題來(lái)了，怎么會(huì)和我打出來(lái)的Log時(shí)間相差這么大？我們先看看系統(tǒng)打出來(lái)的時(shí)間到底是什么時(shí)間。

打出這段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()); } // ...其他代碼 }

它的調(diào)用時(shí)機(jī)我們后面再討論，首先看一下它打出了什么。這個(gè)函數(shù)中將totalTime作為Displayed時(shí)間打了出來(lái)，值為當(dāng)前時(shí)間 - stack.mLaunchStartTime。那這個(gè)mLaunchStartTime是什么時(shí)候被記錄的呢？查了一下調(diào)用發(fā)現(xiàn)在ActivityStackSupervisor.startSpecificActivityLocked會(huì)調(diào)用stack.setLaunchTime(r)去設(shè)置這個(gè)時(shí)間。

那么我們可以得出第一個(gè)結(jié)論：

結(jié)論1：?系統(tǒng)打出來(lái)的時(shí)間包含了進(jìn)程啟動(dòng)的時(shí)間。

因?yàn)檫M(jìn)程啟動(dòng)都是在ActivityStackSupervisor.startSpecificActivityLocked()中進(jìn)行的，以ActivityThread.main為入口啟動(dòng)一個(gè)新進(jìn)程。如果對(duì)于這里不明白，可以參考一下老羅的Android應(yīng)用程序啟動(dòng)過(guò)程源代碼分析。

但是進(jìn)程啟動(dòng)這么耗時(shí)？我的test activiy也沒(méi)有自定義Application，更別提什么耗時(shí)操作了。我來(lái)實(shí)踐一下熱啟動(dòng)，App退出，但是不殺進(jìn)程，再對(duì)比一下我打的log和系統(tǒng)log的時(shí)間區(qū)別。

我：I/MainActivity: onCrete -> onResume : 37
系統(tǒng)： I/ActivityManager: Displayed com.desmond.testapplication/.MainActivity: +103ms

依然差了很多！

看來(lái)我們需要研究一下Activity的onResume過(guò)程及系統(tǒng)上報(bào)Displayed的時(shí)機(jī)了。

深入探究onResume過(guò)程

我先對(duì)AMS觸發(fā)Activity的onResume這個(gè)過(guò)程畫(huà)了一張圖：

在ActivityManagerService(AMS)告知Activity要resume時(shí)，它通過(guò)調(diào)用ApplicationThread.scheduleResumeActivity給ActivityThread.H（一個(gè)Handler）發(fā)送消息RESUME_ACTIVITY，然后H開(kāi)始處理消息：

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

在這個(gè)handleResumeActivity中就處理了所有的Resume邏輯，我們進(jìn)去一探究竟。

? 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); //這步很關(guān)鍵 } } //... } }

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

為什么說(shuō)wm.addView這一步很關(guān)鍵？真正對(duì)Activity的視圖進(jìn)行計(jì)算、繪制、flush到window上是wm.addWindow這一步做的，這里面代碼比較多，我直接畫(huà)張圖看清晰一點(diǎn)：

這張圖的代碼就不放了，關(guān)鍵的類(lèi)和方法都在里面，有興趣的同學(xué)可以自行翻閱。有幾個(gè)注意的點(diǎn)：

Activity#getWindowManager()拿到的是Activity的成員變量mWindowManager，它是一個(gè)WindowManagerIpml實(shí)例，在Activity.attach內(nèi)被賦值。所以我們?cè)诘谝徊街苯泳吞D(zhuǎn)到了WindowManagerImpl.addView()

ViewRootImpl在requestLayout的時(shí)候?qū)⒁粋€(gè)Runnable交由Choreographer去調(diào)度，讓它能夠在下一個(gè)繪制幀時(shí)執(zhí)行它。這個(gè)Runnable內(nèi)只有一條語(yǔ)句，就是執(zhí)行doTraversal，主要的內(nèi)容在其中執(zhí)行的performTraversal中，這個(gè)函數(shù)非常非常長(zhǎng)，做的事情大致就是從頂至下的measure/layout/draw，通知ViewTreeObserver的各類(lèi)Listener也大部分都是在這一步中完成的。

這時(shí)候我們回頭看之前ActivityThread.handleResumeActivity的代碼：Activity的onResume在wm.addView之前！。因?yàn)閂iew的計(jì)算、繪制等都在wm.addView之后執(zhí)行，那我們可以得出第二個(gè)結(jié)論：

結(jié)論2：?在onResume的時(shí)候是肯定統(tǒng)計(jì)不到View的measure/layout/draw時(shí)間的。

這時(shí)候我們要搞清楚的是，上面系統(tǒng)的Log是在哪一步調(diào)用的，它是否包含了View的measure/layout/draw的時(shí)間？這個(gè)過(guò)程可是一頓好找，大概是如下圖所示流程：

5-6步之間被我精簡(jiǎn)了一小部分內(nèi)容，我來(lái)簡(jiǎn)單解釋一下這個(gè)過(guò)程：

ViewRootImpl在performTraversals()的最后會(huì)調(diào)用performDraw()來(lái)將內(nèi)容繪制到Surface上，最后一步它會(huì)執(zhí)行mWindowSession.finishDrawing。這個(gè)mWindowSession是一個(gè)Session對(duì)象，它維持著ViewRootImpl與WindowManagerService(WMS)之間的聯(lián)系。（ViewRootImpl與WMS通信部分可以參考老羅的Android應(yīng)用程序窗口（Activity）與WindowManagerService服務(wù)的連接過(guò)程分析)

在這之后WMS通過(guò)Handler來(lái)調(diào)度繪制Surface的任務(wù)，它給自己內(nèi)部類(lèi)H發(fā)送了一個(gè)DO_TRAVERSAL消息。收到消息之后它就會(huì)執(zhí)行performLayoutAndPlaceSurfacesLocked函數(shù)，之后有一系列的鏈?zhǔn)秸{(diào)用由于方法名字太長(zhǎng)并且于本文沒(méi)有太多用處，在我的圖里被省略了。最后它會(huì)走到performLayoutAndPlaceSurfacesLockedInner，這里面會(huì)將Surface繪制到屏幕上，并調(diào)用handleAppTransitionReadyLocked，并如圖所示繼續(xù)向后調(diào)用。

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

那我們可以確定的是，在看到系統(tǒng)這條日志時(shí)，View的計(jì)算、繪制已經(jīng)完成，并且Surface也被繪制到屏幕上。這樣我們可以得出第三個(gè)結(jié)論：

結(jié)論3：?系統(tǒng)打出來(lái)的日志時(shí)Activity已經(jīng)被完全展示到了屏幕上。

View繪制結(jié)束的回調(diào)時(shí)機(jī)

得出了結(jié)論，那我們要怎么知道什么時(shí)候View繪制結(jié)束呢？這里就仁者見(jiàn)仁，智者見(jiàn)智了。

首先可以確認(rèn)的是，所有ViewTreeObserver里面的Listener都是不夠準(zhǔn)確的。為什么呢？它們里面能統(tǒng)計(jì)到的最遲就是OnDrawListener，我們可以在ViewRootImpl#draw()函數(shù)中看到，它是在真正draw這一步之前調(diào)用的，也就是說(shuō)它沒(méi)有統(tǒng)計(jì)到draw的時(shí)間。

我提供一個(gè)思路，能夠準(zhǔn)確獲取到包括View的measure/layout/draw過(guò)程的時(shí)間。那就是在onResume中添加一個(gè)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; } }); }

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

這里有一個(gè)需要注意的地方：

ViewRootImpl在向Choreographer發(fā)送調(diào)度消息時(shí)，特地向主線程的Looper消息循環(huán)發(fā)送了一個(gè)“障礙消息”。利用MessageQueue#postSyncBarrier可以做到這一點(diǎn)，當(dāng)出現(xiàn)了這一個(gè)障礙消息的時(shí)候，消息循環(huán)就暫時(shí)無(wú)法處理后續(xù)排入消息。有興趣的同學(xué)可以自行研究這個(gè)過(guò)程。

Choreographer通過(guò)直接在native操作主進(jìn)程的MessageQueue來(lái)排入消息，從而它的執(zhí)行會(huì)無(wú)視我們加入的“障礙消息”。（這部分代碼就不深入了，可以參考老羅的Android應(yīng)用程序消息處理機(jī)制（Looper、Handler）分析）。即ViewRootImpl#doTraversal這個(gè)函數(shù)也是在一次消息處理中發(fā)生的。它此時(shí)移除了MessageQueue里面的障礙消息，并且執(zhí)行performTraversals。

需要注意的是：這整個(gè)過(guò)程都是在主線程的消息循環(huán)中發(fā)生的。這個(gè)過(guò)程可以描述為如下幾步：

ActivityThread.H在處理RESUME_ACTIVITY消息時(shí)調(diào)用的handleResumeActivity會(huì)觸發(fā)Activity#onResume與ViewRootImpl#doTraversal。

ViewRootImpl#scheduleTraversals向主進(jìn)程Looper發(fā)送了一個(gè)“障礙消息”，使主進(jìn)程Looper無(wú)法繼續(xù)處理后續(xù)消息。

Choreographer通過(guò)native向主進(jìn)程Looper排入消息，移除“障礙消息”，并執(zhí)行ViewRootImpl#doTraversal。

所以如果我們?cè)趏nResume中向主進(jìn)程添加入一個(gè)IdleHandler，它是必然會(huì)在這三步都走完，主進(jìn)程Looper的MessageQueue才可能觸發(fā)Idle狀態(tài)，并觸發(fā)IdleHandler回調(diào)。

我們可以實(shí)驗(yàn)一下：在添加入的IdleHandler內(nèi)打點(diǎn)，計(jì)算與onCreate第一行打點(diǎn)時(shí)間之差，最后打出來(lái)的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打出來(lái)的差了一點(diǎn)，但是這也是有理由的。我們看上面的WMS繪制Surface那一步，是通過(guò)Handler發(fā)送異步消息完成的，這里統(tǒng)計(jì)不到。

總結(jié)

雖然沒(méi)有完全貼近系統(tǒng)打出來(lái)的日志，但是通過(guò)IdleHandler的方式已經(jīng)能統(tǒng)計(jì)到我想要的內(nèi)容了（由Activity的onCreate第一步到整個(gè)界面顯示）。

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

參考文章：

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

總結(jié)

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

如果覺(jué)得生活随笔網(wǎng)站內(nèi)容還不錯(cuò)，歡迎將生活随笔推薦給好友。