1 /*
<lambda>null2 * Copyright (C) 2023 The Android Open Source Project
3 *
4 * Licensed under the Apache License, Version 2.0 (the "License");
5 * you may not use this file except in compliance with the License.
6 * You may obtain a copy of the License at
7 *
8 * http://www.apache.org/licenses/LICENSE-2.0
9 *
10 * Unless required by applicable law or agreed to in writing, software
11 * distributed under the License is distributed on an "AS IS" BASIS,
12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13 * See the License for the specific language governing permissions and
14 * limitations under the License.
15 */
16
17 package com.android.app.tracing.coroutines
18
19 import android.annotation.SuppressLint
20 import android.os.SystemProperties
21 import android.os.Trace
22 import android.util.Log
23 import com.android.systemui.Flags
24 import java.lang.StackWalker.StackFrame
25 import java.util.concurrent.ThreadLocalRandom
26 import java.util.concurrent.atomic.AtomicInteger
27 import java.util.stream.Stream
28 import kotlin.contracts.ExperimentalContracts
29 import kotlin.contracts.InvocationKind
30 import kotlin.contracts.contract
31 import kotlin.coroutines.CoroutineContext
32 import kotlin.coroutines.EmptyCoroutineContext
33 import kotlinx.coroutines.CopyableThreadContextElement
34 import kotlinx.coroutines.CoroutineScope
35 import kotlinx.coroutines.DelicateCoroutinesApi
36 import kotlinx.coroutines.ExperimentalCoroutinesApi
37
38 /** Use a final subclass to avoid virtual calls (b/316642146). */
39 @PublishedApi internal class TraceDataThreadLocal : ThreadLocal<TraceData?>()
40
41 /**
42 * Thread-local storage for tracking open trace sections in the current coroutine context; it should
43 * only be used when paired with a [TraceContextElement].
44 *
45 * [traceThreadLocal] will be `null` if the code being executed is either 1) not part of coroutine,
46 * or 2) part of a coroutine that does not have a [TraceContextElement] in its context. In both
47 * cases, writing to this thread-local will result in undefined behavior. However, it is safe to
48 * check if [traceThreadLocal] is `null` to determine if coroutine tracing is enabled.
49 *
50 * @see traceCoroutine
51 */
52 @PublishedApi internal val traceThreadLocal: TraceDataThreadLocal = TraceDataThreadLocal()
53
54 private val alwaysEnableStackWalker: Boolean by lazy {
55 SystemProperties.getBoolean("debug.coroutine_tracing.walk_stack_override", false)
56 }
57
58 /**
59 * Returns a new [TraceContextElement] (or [EmptyCoroutineContext] if `coroutine_tracing` feature is
60 * flagged off). This context should only be installed on root coroutines (e.g. when constructing a
61 * `CoroutineScope`). The context will be copied automatically to child scopes and thus should not
62 * be passed to children explicitly.
63 *
64 * [TraceContextElement] should be installed on the root, and [CoroutineTraceName] on the children.
65 *
66 * For example, the following snippet will add trace sections to indicate that `C` is a child of
67 * `B`, and `B` was started by `A`. Perfetto will post-process this information to show that: `A ->
68 * B -> C`
69 *
70 * ```
71 * val scope = CoroutineScope(createCoroutineTracingContext("A")
72 * scope.launch(nameCoroutine("B")) {
73 * // ...
74 * launch(nameCoroutine("C")) {
75 * // ...
76 * }
77 * // ...
78 * }
79 * ```
80 *
81 * **NOTE:** The sysprop `debug.coroutine_tracing.walk_stack_override` can be used to override the
82 * `walkStackForDefaultNames` parameter, forcing it to always be `true`. If the sysprop is `false`
83 * (or does not exist), the value of `walkStackForDefaultNames` is used, whether `true` or `false`.
84 *
85 * @param name the name of the coroutine scope. Since this should only be installed on top-level
86 * coroutines, this should be the name of the root [CoroutineScope].
87 * @param walkStackForDefaultNames whether to walk the stack and use the class name of the current
88 * suspending function if child does not have a name that was manually specified. Walking the
89 * stack is very expensive so this should not be used in production.
90 * @param includeParentNames whether to concatenate parent names and sibling counts with the name of
91 * the child. This should only be used for testing because it can result in extremely long trace
92 * names.
93 * @param strictMode whether to add additional checks to coroutine tracing machinery. These checks
94 * are expensive and should only be used for testing.
95 * @param shouldIgnoreClassName lambda that takes binary class name (as returned from
96 * [StackFrame.getClassName] and returns true if it should be ignored (e.g. search for relevant
97 * class name should continue) or false otherwise
98 */
createCoroutineTracingContextnull99 public fun createCoroutineTracingContext(
100 name: String = "UnnamedScope",
101 walkStackForDefaultNames: Boolean = false,
102 includeParentNames: Boolean = false,
103 strictMode: Boolean = false,
104 shouldIgnoreClassName: (String) -> Boolean = { false },
105 ): CoroutineContext {
106 return if (Flags.coroutineTracing()) {
107 TraceContextElement(
108 name = name,
109 // Minor perf optimization: no need to create TraceData() for root scopes since all
110 // launches require creation of child via [copyForChild] or [mergeForChild].
111 contextTraceData = null,
112 inheritedTracePrefix = "",
113 coroutineDepth = 0,
114 parentId = -1,
115 TraceConfig(
116 walkStackForDefaultNames = walkStackForDefaultNames || alwaysEnableStackWalker,
117 includeParentNames = includeParentNames,
118 strictMode = strictMode,
119 shouldIgnoreClassName = shouldIgnoreClassName,
120 ),
121 )
122 } else {
123 EmptyCoroutineContext
124 }
125 }
126
127 /**
128 * Returns a new [CoroutineTraceName] (or [EmptyCoroutineContext] if `coroutine_tracing` feature is
129 * flagged off). When the current [CoroutineScope] has a [TraceContextElement] installed,
130 * [CoroutineTraceName] can be used to name the child scope under construction.
131 *
132 * [TraceContextElement] should be installed on the root, and [CoroutineTraceName] on the children.
133 */
<lambda>null134 public fun nameCoroutine(name: String): CoroutineContext = nameCoroutine { name }
135
136 /**
137 * Returns a new [CoroutineTraceName] (or [EmptyCoroutineContext] if `coroutine_tracing` feature is
138 * flagged off). When the current [CoroutineScope] has a [TraceContextElement] installed,
139 * [CoroutineTraceName] can be used to name the child scope under construction.
140 *
141 * [TraceContextElement] should be installed on the root, and [CoroutineTraceName] on the children.
142 *
143 * @param name lazy string to only be called if feature is enabled
144 */
145 @OptIn(ExperimentalContracts::class)
nameCoroutinenull146 public inline fun nameCoroutine(name: () -> String): CoroutineContext {
147 contract { callsInPlace(name, InvocationKind.AT_MOST_ONCE) }
148 return if (Flags.coroutineTracing()) CoroutineTraceName(name()) else EmptyCoroutineContext
149 }
150
151 /**
152 * Common base class of [TraceContextElement] and [CoroutineTraceName]. For internal use only.
153 *
154 * [TraceContextElement] should be installed on the root, and [CoroutineTraceName] on the children.
155 *
156 * @property name the name of the current coroutine
157 */
158 /**
159 * A coroutine context element that can be used for naming the child coroutine under construction.
160 *
161 * @property name the name to be used for the child under construction
162 * @see nameCoroutine
163 */
164 @PublishedApi
165 internal open class CoroutineTraceName(internal val name: String) : CoroutineContext.Element {
166 internal companion object Key : CoroutineContext.Key<CoroutineTraceName>
167
168 public override val key: CoroutineContext.Key<*>
169 get() = Key
170
171 protected val currentId: Int = ThreadLocalRandom.current().nextInt(1, Int.MAX_VALUE)
172
173 @Deprecated(
174 message =
175 """
176 Operator `+` on two BaseTraceElement objects is meaningless. If used, the context element
177 to the right of `+` would simply replace the element to the left. To properly use
178 `BaseTraceElement`, `TraceContextElement` should be used when creating a top-level
179 `CoroutineScope` and `CoroutineTraceName` should be passed to the child context that is
180 under construction.
181 """,
182 level = DeprecationLevel.ERROR,
183 )
plusnull184 public operator fun plus(other: CoroutineTraceName): CoroutineTraceName {
185 debug { "#plus(${other.currentId})" }
186 return other
187 }
188
189 @OptIn(ExperimentalContracts::class)
debugnull190 protected inline fun debug(message: () -> String) {
191 contract { callsInPlace(message, InvocationKind.AT_MOST_ONCE) }
192 if (DEBUG) Log.d(TAG, "${this::class.java.simpleName}@$currentId${message()}")
193 }
194 }
195
196 internal data class TraceConfig(
197 val walkStackForDefaultNames: Boolean,
198 val includeParentNames: Boolean,
199 val strictMode: Boolean,
200 val shouldIgnoreClassName: (String) -> Boolean,
201 )
202
203 /**
204 * Used for tracking parent-child relationship of coroutines and persisting [TraceData] when
205 * coroutines are suspended and resumed.
206 *
207 * This is internal machinery for [traceCoroutine] and should not be used directly.
208 *
209 * @param name the name of the current coroutine. Since this should only be installed on top-level
210 * coroutines, this should be the name of the root [CoroutineScope].
211 * @property contextTraceData [TraceData] to be saved to thread-local storage.
212 * @param inheritedTracePrefix prefix containing metadata for parent scopes. Each child is separated
213 * by a `:` and prefixed by a counter indicating the ordinal of this child relative to its
214 * siblings. Thus, the prefix such as `root-name:3^child-name` would indicate this is the 3rd
215 * child (of any name) to be started on `root-scope`. If the child has no name, an empty string
216 * would be used instead: `root-scope:3^`
217 * @property coroutineDepth how deep the coroutine is relative to the top-level [CoroutineScope]
218 * containing the original [TraceContextElement] from which this [TraceContextElement] was copied.
219 * @param parentId the ID of the parent coroutine, as defined in [BaseTraceElement]
220 * @param walkStackForDefaultNames whether to walk the stack and use the class name of the current
221 * suspending function if child does not have a name that was manually specified. Walking the
222 * stack is very expensive so this should not be used in production.
223 * @param includeParentNames whether to concatenate parent names and sibling counts with the name of
224 * the child. This should only be used for testing because it can result in extremely long trace
225 * names.
226 * @param strictMode whether to add additional checks to coroutine machinery. These checks are
227 * expensive and should only be used for testing.
228 * @param shouldIgnoreClassName lambda that takes binary class name (as returned from
229 * [StackFrame.getClassName] and returns true if it should be ignored (e.g. search for relevant
230 * class name should continue) or false otherwise
231 * @see createCoroutineTracingContext
232 * @see nameCoroutine
233 * @see traceCoroutine
234 */
235 @OptIn(DelicateCoroutinesApi::class, ExperimentalCoroutinesApi::class)
236 internal class TraceContextElement(
237 name: String,
238 internal val contextTraceData: TraceData?,
239 inheritedTracePrefix: String,
240 private val coroutineDepth: Int,
241 parentId: Int,
242 private val config: TraceConfig,
243 ) : CopyableThreadContextElement<TraceData?>, CoroutineTraceName(name) {
244
245 private var childCoroutineCount = AtomicInteger(0)
246
247 private val fullCoroutineTraceName =
248 if (config.includeParentNames) "$inheritedTracePrefix$name" else ""
249 private val continuationTraceMessage =
250 "$fullCoroutineTraceName;$name;d=$coroutineDepth;c=$currentId;p=$parentId"
251
252 init {
<lambda>null253 debug { "#init: name=$name" }
254 Trace.instant(Trace.TRACE_TAG_APP, continuationTraceMessage)
255 }
256
257 /**
258 * This function is invoked before the coroutine is resumed on the current thread. When a
259 * multi-threaded dispatcher is used, calls to `updateThreadContext` may happen in parallel to
260 * the prior `restoreThreadContext` in the same context. However, calls to `updateThreadContext`
261 * will not run in parallel on the same context.
262 *
263 * ```
264 * Thread #1 | [updateThreadContext]....^ [restoreThreadContext]
265 * --------------------------------------------------------------------------------------------
266 * Thread #2 | [updateThreadContext]...........^[restoreThreadContext]
267 * ```
268 *
269 * (`...` indicate coroutine body is running; whitespace indicates the thread is not scheduled;
270 * `^` is a suspension point)
271 */
272 @SuppressLint("UnclosedTrace")
updateThreadContextnull273 public override fun updateThreadContext(context: CoroutineContext): TraceData? {
274 val oldState = traceThreadLocal.get()
275 debug { "#updateThreadContext oldState=$oldState" }
276 if (oldState !== contextTraceData) {
277 Trace.traceBegin(Trace.TRACE_TAG_APP, continuationTraceMessage)
278 traceThreadLocal.set(contextTraceData)
279 // Calls to `updateThreadContext` will not happen in parallel on the same context, and
280 // they cannot happen before the prior suspension point. Additionally,
281 // `restoreThreadContext` does not modify `traceData`, so it is safe to iterate over the
282 // collection here:
283 contextTraceData?.beginAllOnThread()
284 }
285 return oldState
286 }
287
288 /**
289 * This function is invoked after the coroutine has suspended on the current thread. When a
290 * multi-threaded dispatcher is used, calls to `restoreThreadContext` may happen in parallel to
291 * the subsequent `updateThreadContext` and `restoreThreadContext` operations. The coroutine
292 * body itself will not run in parallel, but `TraceData` could be modified by a coroutine body
293 * after the suspension point in parallel to `restoreThreadContext` associated with the
294 * coroutine body _prior_ to the suspension point.
295 *
296 * ```
297 * Thread #1 | [updateThreadContext].x..^ [restoreThreadContext]
298 * --------------------------------------------------------------------------------------------
299 * Thread #2 | [updateThreadContext]..x..x.....^[restoreThreadContext]
300 * ```
301 *
302 * OR
303 *
304 * ```
305 * Thread #1 | [restoreThreadContext]
306 * --------------------------------------------------------------------------------------------
307 * Thread #2 | [updateThreadContext]...x....x..^[restoreThreadContext]
308 * ```
309 *
310 * (`...` indicate coroutine body is running; whitespace indicates the thread is not scheduled;
311 * `^` is a suspension point; `x` are calls to modify the thread-local trace data)
312 *
313 * ```
314 */
restoreThreadContextnull315 public override fun restoreThreadContext(context: CoroutineContext, oldState: TraceData?) {
316 debug { "#restoreThreadContext restoring=$oldState" }
317 // We not use the `TraceData` object here because it may have been modified on another
318 // thread after the last suspension point. This is why we use a [TraceStateHolder]:
319 // so we can end the correct number of trace sections, restoring the thread to its state
320 // prior to the last call to [updateThreadContext].
321 if (oldState !== traceThreadLocal.get()) {
322 contextTraceData?.endAllOnThread()
323 traceThreadLocal.set(oldState)
324 Trace.traceEnd(Trace.TRACE_TAG_APP) // end: currentScopeTraceMessage
325 }
326 }
327
copyForChildnull328 public override fun copyForChild(): CopyableThreadContextElement<TraceData?> {
329 debug { "#copyForChild" }
330 return createChildContext()
331 }
332
mergeForChildnull333 public override fun mergeForChild(
334 overwritingElement: CoroutineContext.Element
335 ): CoroutineContext {
336 debug { "#mergeForChild" }
337 if (DEBUG) {
338 (overwritingElement as? TraceContextElement)?.let {
339 Log.e(
340 TAG,
341 "${this::class.java.simpleName}@$currentId#mergeForChild(@${it.currentId}): " +
342 "current name=\"$name\", overwritingElement name=\"${it.name}\". " +
343 UNEXPECTED_TRACE_DATA_ERROR_MESSAGE,
344 )
345 }
346 }
347 val nameForChild = (overwritingElement as CoroutineTraceName).name
348 return createChildContext(nameForChild)
349 }
350
createChildContextnull351 private fun createChildContext(
352 name: String =
353 if (config.walkStackForDefaultNames) walkStackForClassName(config.shouldIgnoreClassName)
354 else ""
355 ): TraceContextElement {
356 debug { "#createChildContext: \"$name\" has new child with name \"${name}\"" }
357 val childCount = childCoroutineCount.incrementAndGet()
358 return TraceContextElement(
359 name = name,
360 contextTraceData = TraceData(config.strictMode),
361 inheritedTracePrefix =
362 if (config.includeParentNames) "$fullCoroutineTraceName:$childCount^" else "",
363 coroutineDepth = coroutineDepth + 1,
364 parentId = currentId,
365 config = config,
366 )
367 }
368 }
369
370 /**
371 * Get a name for the trace section include the name of the call site.
372 *
373 * @param additionalDropPredicate additional checks for whether class should be ignored
374 */
walkStackForClassNamenull375 private fun walkStackForClassName(
376 additionalDropPredicate: (String) -> Boolean = { false }
377 ): String {
378 Trace.traceBegin(Trace.TRACE_TAG_APP, "walkStackForClassName")
379 try {
380 var frame = ""
snull381 StackWalker.getInstance().walk { s: Stream<StackFrame> ->
382 s.dropWhile { f: StackFrame ->
383 val className = f.className
384 className.startsWith("kotlin") ||
385 className.startsWith("com.android.app.tracing.") ||
386 additionalDropPredicate(className)
387 }
388 .findFirst()
389 .ifPresent { frame = it.className.substringAfterLast(".") + "." + it.methodName }
390 }
391 return frame
392 } catch (e: Exception) {
393 if (DEBUG) Log.e(TAG, "Error walking stack to infer a trace name", e)
394 return ""
395 } finally {
396 Trace.traceEnd(Trace.TRACE_TAG_APP)
397 }
398 }
399
400 private const val UNEXPECTED_TRACE_DATA_ERROR_MESSAGE =
401 "Overwriting context element with non-empty trace data. There should only be one " +
402 "TraceContextElement per coroutine, and it should be installed in the root scope. "
403
404 @PublishedApi internal const val TAG: String = "CoroutineTracing"
405
406 @PublishedApi internal const val DEBUG: Boolean = false
407