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.util.Preconditions
13 
14 /** Logger for logging Launcher activity's startup latency. */
15 open class ColdRebootStartupLatencyLogger : StartupLatencyLogger {
16 
17     companion object {
18         const val TAG = "ColdRebootStartupLatencyLogger"
19         const val UNSET_INT = -1
20         const val UNSET_LONG = -1L
21     }
22 
23     @VisibleForTesting(otherwise = VisibleForTesting.PROTECTED)
24     val startTimeByEvent = SparseLongArray()
25     @VisibleForTesting(otherwise = VisibleForTesting.PROTECTED)
26     val endTimeByEvent = SparseLongArray()
27 
28     @VisibleForTesting(otherwise = VisibleForTesting.PROTECTED) var cardinality: Int = UNSET_INT
29     @VisibleForTesting(otherwise = VisibleForTesting.PROTECTED)
30     var workspaceLoadStartTime: Long = UNSET_LONG
31 
32     // ColdRebootStartupLatencyLogger should only send launcher startup logs once in each launcher
33     // activity lifecycle. After launcher activity startup is completed, the logger should be torn
34     // down and reject all logging calls. This flag should be checked at all APIs to prevent logging
35     // invalid startup metrics (such as loading workspace in screen rotation).
36     var isTornDown = false
37     private var isInTest = false
38 
39     /** Subclass can override this method to handle collected latency metrics. */
40     @MainThread
lognull41     override fun log(): ColdRebootStartupLatencyLogger {
42         return this
43     }
44 
45     @MainThread
logWorkspaceLoadStartTimenull46     override fun logWorkspaceLoadStartTime() =
47         logWorkspaceLoadStartTime(SystemClock.elapsedRealtime())
48 
49     @VisibleForTesting
50     @MainThread
51     fun logWorkspaceLoadStartTime(startTimeMs: Long): ColdRebootStartupLatencyLogger {
52         Preconditions.assertUIThread()
53         if (isTornDown) {
54             return this
55         }
56         workspaceLoadStartTime = startTimeMs
57         return this
58     }
59 
60     /**
61      * Log size of workspace. Larger number of workspace items (icons, folders, widgets) means
62      * longer latency to initialize workspace.
63      */
64     @MainThread
logCardinalitynull65     override fun logCardinality(cardinality: Int): ColdRebootStartupLatencyLogger {
66         Preconditions.assertUIThread()
67         if (isTornDown) {
68             return this
69         }
70         this.cardinality = cardinality
71         return this
72     }
73 
74     @MainThread
logStartnull75     override fun logStart(event: LauncherLatencyEvent) =
76         logStart(event, SystemClock.elapsedRealtime())
77 
78     @MainThread
79     override fun logStart(
80         event: LauncherLatencyEvent,
81         startTimeMs: Long
82     ): ColdRebootStartupLatencyLogger {
83         // In unit test no looper is attached to current thread
84         Preconditions.assertUIThread()
85         if (isTornDown) {
86             return this
87         }
88         if (validateLoggingEventAtStart(event)) {
89             startTimeByEvent.put(event.id, startTimeMs)
90         }
91         return this
92     }
93 
94     @MainThread
logEndnull95     override fun logEnd(event: LauncherLatencyEvent) = logEnd(event, SystemClock.elapsedRealtime())
96 
97     @MainThread
98     override fun logEnd(
99         event: LauncherLatencyEvent,
100         endTimeMs: Long
101     ): ColdRebootStartupLatencyLogger {
102         // In unit test no looper is attached to current thread
103         Preconditions.assertUIThread()
104         if (isTornDown) {
105             return this
106         }
107         maybeLogStartOfWorkspaceLoadTime(event)
108         if (validateLoggingEventAtEnd(event)) {
109             endTimeByEvent.put(event.id, endTimeMs)
110         }
111 
112         return this
113     }
114 
115     @MainThread
resetnull116     override fun reset() {
117         // In unit test no looper is attached to current thread
118         Preconditions.assertUIThread()
119         startTimeByEvent.clear()
120         endTimeByEvent.clear()
121         cardinality = UNSET_INT
122         workspaceLoadStartTime = UNSET_LONG
123         isTornDown = true
124     }
125 
126     @MainThread
maybeLogStartOfWorkspaceLoadTimenull127     private fun maybeLogStartOfWorkspaceLoadTime(event: LauncherLatencyEvent) {
128         if (workspaceLoadStartTime == UNSET_LONG) {
129             return
130         }
131         if (event == LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_WORKSPACE_LOADER_ASYNC) {
132             logStart(event, workspaceLoadStartTime)
133             workspaceLoadStartTime = UNSET_LONG
134         }
135     }
136 
137     /** @return true if we can log start of [LauncherLatencyEvent] and vice versa. */
138     @MainThread
validateLoggingEventAtStartnull139     private fun validateLoggingEventAtStart(event: LauncherLatencyEvent): Boolean {
140         if (!BuildConfig.IS_STUDIO_BUILD && !isInTest) {
141             return true
142         }
143         if (startTimeByEvent.contains(event.id)) {
144             Log.e(TAG, "Cannot restart same ${event.name} event")
145             return false
146         } else if (
147             startTimeByEvent.isEmpty() &&
148                 event != LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION
149         ) {
150             Log.e(
151                 TAG,
152                 "The first log start event must be " +
153                     "${LauncherLatencyEvent.LAUNCHER_LATENCY_STARTUP_TOTAL_DURATION.name}.",
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