adb 如何衡量應用啟動

語言: CN / TW / HK

可以利用 ActivityTaskManager 的輸出來獲取應用程式啟動持續時間。

每當 Activity 啟動時,都會在 logcat 輸出中看到類似的內容:

ActivityTaskManager: Displayed com.android.samples.mytest/.MainActivity: +1s380ms

此持續時間(在此示例中為 1,380 毫秒)表示從啟動應用程式到系統認為它“已啟動”的時間,其中包括繪製第一幀(因此為“已顯示”)。

這篇文章深入探討了這個問題:

ActivityTaskManager 究竟測量什麼?

ActivityTaskManager 測量從 system_process 接收到啟動活動的意圖到該活動的視窗完成繪製的時間(API < 30 上的正常執行時間,API 30+ 上的實時時間)。

關鍵要點:

此度量包括應用程式程式碼和資源載入之前的幾百毫秒,即應用程式開發人員無法影響的時間。

可以在應用程式內進行測量而無需額外的時間,我將在最後分享如何進行。

ActivityTaskManager log

ActivityTaskManager: Displayed com.android.samples.mytest/.MainActivity: +1s380ms

我們知道日誌的樣子,所以我們可以在 cs.android.com 上搜索它:\"Displayed\"

這導致我們到 ActivityTaskManager.logAppDisplayed(): private void logAppDisplayed(TransitionInfoSnapshot info) { StringBuilder sb = mStringBuilder; sb.setLength(0); sb.append("Displayed "); sb.append(info.launchedActivityShortComponentName); sb.append(": "); TimeUtils.formatDuration(info.windowsDrawnDelayMs, sb); Log.i(TAG, sb.toString()); }

啟動持續時間為 TransitionInfoSnapshot.windowsDrawnDelayMs。 它在 TransitionInfoSnapshot.notifyWindowsDrawn() 中計算: ``` TransitionInfoSnapshot notifyWindowsDrawn( ActivityRecord r, long timestampNs ) {
TransitionInfo info = getActiveTransitionInfo(r); info.mWindowsDrawnDelayMs = info.calculateDelay(timestampNs); return new TransitionInfoSnapshot(info); }

private static final class TransitionInfo { int calculateDelay(long timestampNs) { long delayNanos = timestampNs - mTransitionStartTimeNs; return (int) TimeUnit.NANOSECONDS.toMillis(delayNanos); } } ```

讓我們找出 timestampNs 和 mTransitionStartTimeNs 在哪裡被捕獲。

ActivityMetricsLogger.notifyActivityLaunching() 捕獲活動轉換的開始: private LaunchingState notifyActivityLaunching( Intent intent, ActivityRecord caller, int callingUid ) { long transitionStartNs = SystemClock.elapsedRealtimeNanos(); LaunchingState launchingState = new LaunchingState(); launchingState.mCurrentTransitionStartTimeNs = transitionStartNs; return launchingState; }

TransitionInfoSnapshot.notifyWindowsDrawn() 由 ActivityRecord.onWindowsDrawn() 呼叫,後者由 ActivityRecord.updateReportedVisibilityLocked() 呼叫: void updateReportedVisibilityLocked() { // ... if (nowDrawn != reportedDrawn) { onWindowsDrawn(nowDrawn, SystemClock.elapsedRealtimeNanos()); reportedDrawn = nowDrawn; } // ... }

我們現在知道在哪裡捕獲開始和結束時間戳,但不幸的是 ActivityMetricsLogger.notifyActivityLaunching() 和 ActivityRecord.updateReportedVisibilityLocked() 有很多呼叫點,因此很難在 AOSP 源中進一步挖掘。

除錯system_process

我告訴一個朋友,我在檢視 Android 資源時遇到了死衚衕,他問我:

為什麼不設定斷點?

我從未嘗試過除錯 system_process,但我們沒有理由不能。 謝謝文森特的主意! 幸運的是,Android Studio 設定為查詢應用編譯所針對的 Android 版本的原始碼。

使用 Root 裝置,我可以將偵錯程式連線到 system_process。

當我啟動我的應用程式時,我遇到了 ActivityMetricsLogger.notifyActivityLaunching() 的斷點。

和 TransitionInfoSnapshot.notifyWindowsDrawn() 的另一個斷點。

讀取堆疊跟蹤

第一個堆疊跟蹤顯示當 system_process 收到啟動活動的 Intent 時捕獲開始時間戳。

第二個堆疊跟蹤顯示當該活動的視窗完成繪製時捕獲結束時間戳。 相應的幀應在 16 毫秒內在顯示屏上可見。

應用啟動時間

啟動 Activity 的使用者體驗在使用者觸控式螢幕幕時開始,但是應用程式開發人員對 ActivityThread.handleBindApplication() 之前花費的時間幾乎沒有影響,因此應用程式冷啟動監控應該從這裡開始。

ActivityThread.handleBindApplication() 載入 APK 和應用程式元件(AppComponentFactory、ContentProvider、Application)。 不幸的是,ActivityTaskManager 使用 ActivityTaskManagerService.startActivity() 作為開始時間,它發生在 ActivityThread.handleBindApplication() 之前的一段時間。

ActivityTaskManager 增加了多少時間?

我展示了我們可以使用 Process.getStartUptimeMillis() 來獲取呼叫 ActivityThread.handleBindApplication() 的時間戳。 我還分享了一個程式碼片段來讀取程序 fork 時間(參見 Processes.readProcessForkRealtimeMillis())。 我們可以將這 2 個值記錄到 logcat: ``` val forkRealtime = Processes.readProcessForkRealtimeMillis() val nowRealtimeMs = SystemClock.elapsedRealtime() val nowUptimeMs = SystemClock.uptimeMillis() val elapsedRealtimeMs = nowRealtimeMs - forkRealtime val forkUptimeMs = nowUptimeMs - elapsedRealtimeMs Log.d("AppStart", "$forkUptimeMs fork timestamp")

val processStart = Process.getStartUptimeMillis() Log.d("AppStart", "$processStart bindApplication() timestamp") ```

我們還需要記錄 ActivityMetricsLogger.mCurrentTransitionStartTime。 我們可以讓我們之前的 system_process 斷點非掛起並讓它記錄值。 Evaluate 和 log 的輸出進入偵錯程式控制檯。 我們希望所有日誌都在 logcat 中,因此我們從那裡呼叫 Log.d()。

結果

D/AppStart: 27464211 Intent received D/AppStart: 27464340 fork timestamp D/AppStart: 27464533 bindApplication() timestamp ... I/ActivityTaskManager: Displayed com.example.logstartup/.MainActivity: +1s185ms

從接收到分叉 zygote 程序的意圖需要 129 毫秒,從分叉到 ActivityThread.handleBindApplication() 需要 193 毫秒,即應用程式開始載入其程式碼和資源之前的 322 毫秒。 在此示例中,這是 ActivityTaskManager 報告的應用啟動時間的約 30%。

實際數字低於此值,因為 system_process 正在執行並連線偵錯程式。

從應用程式內部測量應用程式啟動時間

我將該時間戳與傳遞給 TransitionInfoSnapshot.notifyWindowsDrawn() 的時間戳進行了比較,這兩個值僅相隔幾毫秒。

我們可以把我們學到的東西放在一起來衡量應用程式內的應用程式啟動持續時間: ``` class MyApp : Application() {

override fun onCreate() { super.onCreate()

var firstDraw = false
val handler = Handler()

registerActivityLifecycleCallbacks(
  object : ActivityLifecycleCallbacks {
  override fun onActivityCreated(
    activity: Activity,
    savedInstanceState: Bundle?
  ) {
    if (firstDraw) return
    val name = activity::class.java.simpleName
    val window = activity.window
    window.onDecorViewReady {
      window.decorView.onNextDraw {
        if (firstDraw) [email protected]
        firstDraw = true
        handler.postAtFrontOfQueue {
          val start = Process.getStartUptimeMillis()
          val now = SystemClock.uptimeMillis()
          val startDurationMs = now - start
          Log.d(
            "AppStart", 
            "Displayed $name in $startDurationMs ms"
          )
        }
      }
    }
  }
})

} } ```

D/AppStart: Displayed MainActivity in 863 ms

結論

ActivityTaskManager 的輸出很方便,如果您嘗試比較應用程式不同版本的啟動時間,則完全值得使用。 請注意,應用程式開發人員無法影響那段時間的重要部分。

可以從應用程式內測量應用程式啟動時間。