1 package com.android.launcher3.logging 2 3 import android.os.SystemClock 4 import android.util.Log 5 import android.util.SparseLongArray 6 import androidx.annotation.MainThread 7 import androidx.annotation.VisibleForTesting 8 import androidx.core.util.contains 9 import androidx.core.util.isEmpty 10 import com.android.launcher3.BuildConfig 11 import com.android.launcher3.logging.StatsLogManager.LauncherLatencyEvent 12 import com.android.launcher3.logging.StatsLogManager.StatsLatencyLogger.LatencyType 13 import com.android.launcher3.util.Preconditions 14 15 /** Logger for logging Launcher activity's startup latency. */ 16 open class StartupLatencyLogger(val latencyType: LatencyType) { 17 18 companion object { 19 const val TAG = "LauncherStartupLatencyLogger" 20 const val UNSET_INT = -1 21 const val UNSET_LONG = -1L 22 } 23 24 @VisibleForTesting(otherwise = VisibleForTesting.PROTECTED) 25 val startTimeByEvent = SparseLongArray() 26 @VisibleForTesting(otherwise = VisibleForTesting.PROTECTED) 27 val endTimeByEvent = SparseLongArray() 28 29 @VisibleForTesting(otherwise = VisibleForTesting.PROTECTED) var cardinality: Int = UNSET_INT 30 @VisibleForTesting(otherwise = VisibleForTesting.PROTECTED) 31 var workspaceLoadStartTime: Long = UNSET_LONG 32 33 private var isInTest = false 34 35 /** Subclass can override this method to handle collected latency metrics. */ 36 @MainThread lognull37 open fun log(): StartupLatencyLogger { 38 return this 39 } 40 41 @MainThread logWorkspaceLoadStartTimenull42 fun logWorkspaceLoadStartTime() = logWorkspaceLoadStartTime(SystemClock.elapsedRealtime()) 43 44 @VisibleForTesting 45 @MainThread 46 fun logWorkspaceLoadStartTime(startTimeMs: Long): StartupLatencyLogger { 47 Preconditions.assertUIThread() 48 workspaceLoadStartTime = startTimeMs 49 return this 50 } 51 52 /** 53 * Log size of workspace. Larger number of workspace items (icons, folders, widgets) means 54 * longer latency to initialize workspace. 55 */ 56 @MainThread logCardinalitynull57 fun logCardinality(cardinality: Int): StartupLatencyLogger { 58 Preconditions.assertUIThread() 59 this.cardinality = cardinality 60 return this 61 } 62 63 @MainThread logStartnull64 fun logStart(event: LauncherLatencyEvent) = logStart(event, SystemClock.elapsedRealtime()) 65 66 @MainThread 67 fun logStart(event: LauncherLatencyEvent, startTimeMs: Long): StartupLatencyLogger { 68 // In unit test no looper is attached to current thread 69 Preconditions.assertUIThread() 70 if (validateLoggingEventAtStart(event)) { 71 startTimeByEvent.put(event.id, startTimeMs) 72 } 73 return this 74 } 75 76 @MainThread logEndnull77 fun logEnd(event: LauncherLatencyEvent) = logEnd(event, SystemClock.elapsedRealtime()) 78 79 @MainThread 80 fun logEnd(event: LauncherLatencyEvent, endTimeMs: Long): StartupLatencyLogger { 81 // In unit test no looper is attached to current thread 82 Preconditions.assertUIThread() 83 maybeLogStartOfWorkspaceLoadTime(event) 84 if (validateLoggingEventAtEnd(event)) { 85 endTimeByEvent.put(event.id, endTimeMs) 86 } 87 88 return this 89 } 90 91 @MainThread resetnull92 fun reset() { 93 // In unit test no looper is attached to current thread 94 Preconditions.assertUIThread() 95 startTimeByEvent.clear() 96 endTimeByEvent.clear() 97 cardinality = UNSET_INT 98 workspaceLoadStartTime = UNSET_LONG 99 } 100 101 @MainThread maybeLogStartOfWorkspaceLoadTimenull102 private fun maybeLogStartOfWorkspaceLoadTime(event: LauncherLatencyEvent) { 103 if (workspaceLoadStartTime == UNSET_LONG) { 104 return 105 } 106 if ( 107 event == LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_SYNC || 108 event == LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC 109 ) { 110 logStart(event, workspaceLoadStartTime) 111 workspaceLoadStartTime = UNSET_LONG 112 } 113 } 114 115 /** @return true if we can log start of [LauncherLatencyEvent] and vice versa. */ 116 @MainThread validateLoggingEventAtStartnull117 private fun validateLoggingEventAtStart(event: LauncherLatencyEvent): Boolean { 118 if (!BuildConfig.IS_STUDIO_BUILD && !isInTest) { 119 return true 120 } 121 if (startTimeByEvent.contains(event.id)) { 122 Log.e(TAG, "Cannot restart same ${event.name} event") 123 return false 124 } else if ( 125 startTimeByEvent.isEmpty() && 126 event != LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION 127 ) { 128 Log.e( 129 TAG, 130 "The first log start event must be " + 131 "${LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION.name}.", 132 ) 133 return false 134 } else if ( 135 event == LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_SYNC && 136 startTimeByEvent.get( 137 LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC.id 138 ) != 0L 139 ) { 140 Log.e( 141 TAG, 142 "Cannot start ${LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_SYNC.name} event after ${LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC.name} starts", 143 ) 144 return false 145 } else if ( 146 event == LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC && 147 startTimeByEvent.get( 148 LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_SYNC.id 149 ) != 0L 150 ) { 151 Log.e( 152 TAG, 153 "Cannot start ${LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC.name} event after ${LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_SYNC.name} starts", 154 ) 155 return false 156 } 157 158 return true 159 } 160 161 /** @return true if we can log end of [LauncherLatencyEvent] and vice versa. */ 162 @MainThread validateLoggingEventAtEndnull163 private fun validateLoggingEventAtEnd(event: LauncherLatencyEvent): Boolean { 164 if (!BuildConfig.IS_STUDIO_BUILD && !isInTest) { 165 return true 166 } 167 if (!startTimeByEvent.contains(event.id)) { 168 Log.e(TAG, "Cannot end ${event.name} event before starting it") 169 return false 170 } else if (endTimeByEvent.contains(event.id)) { 171 Log.e(TAG, "Cannot end same ${event.name} event again") 172 return false 173 } else if ( 174 event != LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION && 175 endTimeByEvent.contains( 176 LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION.id 177 ) 178 ) { 179 Log.e( 180 TAG, 181 "Cannot end ${event.name} event after ${LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION.name}", 182 ) 183 return false 184 } 185 return true 186 } 187 188 @VisibleForTesting setIsInTestnull189 fun setIsInTest() { 190 isInTest = true 191 } 192 } 193