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.PerfettoTrace
21 import android.os.SystemProperties
22 import android.os.Trace
23 import android.util.Log
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.AbstractCoroutineContextKey
32 import kotlin.coroutines.CoroutineContext
33 import kotlin.coroutines.EmptyCoroutineContext
34 import kotlin.coroutines.getPolymorphicElement
35 import kotlin.coroutines.minusPolymorphicKey
36 import kotlinx.coroutines.CopyableThreadContextElement
37 import kotlinx.coroutines.CoroutineScope
38 import kotlinx.coroutines.DelicateCoroutinesApi
39 import kotlinx.coroutines.ExperimentalCoroutinesApi
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 internal object DebugSysProps {
55 @JvmField
56 val alwaysEnableStackWalker =
57 SystemProperties.getBoolean("debug.coroutine_tracing.walk_stack_override", false)
58
59 @JvmField
60 val alwaysEnableContinuationCounting =
61 SystemProperties.getBoolean("debug.coroutine_tracing.count_continuations_override", false)
62 }
63
64 /**
65 * Returns a new [TraceContextElement] (or [EmptyCoroutineContext] if `coroutine_tracing` feature is
66 * flagged off). This context should only be installed on root coroutines (e.g. when constructing a
67 * `CoroutineScope`). The context will be copied automatically to child scopes and thus should not
68 * be passed to children explicitly.
69 *
70 * [TraceContextElement] should be installed on the root, and [CoroutineTraceName] on the children.
71 *
72 * For example, the following snippet will add trace sections to indicate that `C` is a child of
73 * `B`, and `B` was started by `A`. Perfetto will post-process this information to show that: `A ->
74 * B -> C`
75 *
76 * ```
77 * val scope = CoroutineScope(createCoroutineTracingContext("A")
78 * scope.launch(nameCoroutine("B")) {
79 * // ...
80 * launch(nameCoroutine("C")) {
81 * // ...
82 * }
83 * // ...
84 * }
85 * ```
86 *
87 * **NOTE:** The sysprops `debug.coroutine_tracing.walk_stack_override` and
88 * `debug.coroutine_tracing.count_continuations_override` can be used to override the parameters
89 * `walkStackForDefaultNames` and `countContinuations` respectively, forcing them to always be
90 * `true`. If the sysprop is `false` (or does not exist), the value of the parameter is passed here
91 * is used. If `true`, all calls to [createCoroutineTracingContext] will be overwritten with that
92 * parameter set to `true`. Importantly, this means that the sysprops can be used to globally turn
93 * ON `walkStackForDefaultNames` or `countContinuations`, but they cannot be used to globally turn
94 * OFF either parameter.
95 *
96 * @param name the name of the coroutine scope. Since this should only be installed on top-level
97 * coroutines, this should be the name of the root [CoroutineScope].
98 * @param walkStackForDefaultNames whether to walk the stack and use the class name of the current
99 * suspending function if child does not have a name that was manually specified. Walking the
100 * stack is very expensive so this should not be used in production.
101 * @param countContinuations whether to include extra info in the trace section indicating the total
102 * number of times a coroutine has suspended and resumed (e.g. ";n=#")
103 * @param countDepth whether to include extra info in the trace section indicating the how far from
104 * the root trace context this coroutine is (e.g. ";d=#")
105 * @param testMode changes behavior is several ways: 1) parent names and sibling counts are
106 * concatenated with the name of the child. This can result in extremely long trace names, which
107 * is why it is only for testing. 2) additional strict-mode checks are added to coroutine tracing
108 * machinery. These checks are expensive and should only be used for testing. 3) omits "coroutine
109 * execution" trace slices, and omits coroutine metadata slices. If [testMode] is enabled,
110 * [countContinuations] and [countDepth] are ignored.
111 * @param shouldIgnoreClassName lambda that takes binary class name (as returned from
112 * [StackFrame.getClassName] and returns true if it should be ignored (e.g. search for relevant
113 * class name should continue) or false otherwise.
114 */
createCoroutineTracingContextnull115 public fun createCoroutineTracingContext(
116 name: String = "UnnamedScope",
117 countContinuations: Boolean = false,
118 countDepth: Boolean = false,
119 testMode: Boolean = false,
120 walkStackForDefaultNames: Boolean = false,
121 shouldIgnoreClassName: ((String) -> Boolean)? = null,
122 ): CoroutineContext {
123 return if (com.android.systemui.Flags.coroutineTracing()) {
124 TraceContextElement(
125 name = name,
126 isRoot = true,
127 countContinuations =
128 !testMode && (countContinuations || DebugSysProps.alwaysEnableContinuationCounting),
129 walkStackForDefaultNames =
130 walkStackForDefaultNames || DebugSysProps.alwaysEnableStackWalker,
131 shouldIgnoreClassName = shouldIgnoreClassName,
132 parentId = null,
133 inheritedTracePrefix = if (testMode) "" else null,
134 coroutineDepth = if (!testMode && countDepth) 0 else -1,
135 )
136 } else {
137 EmptyCoroutineContext
138 }
139 }
140
141 private object PerfettoTraceConfig {
142 // cc = coroutine continuations
143 @JvmField val COROUTINE_CATEGORY: PerfettoTrace.Category = PerfettoTrace.Category("cc")
144
145 init {
146 if (android.os.Flags.perfettoSdkTracingV2()) {
147 PerfettoTrace.register(/* isBackendInProcess */ false)
148 COROUTINE_CATEGORY.register()
149 }
150 }
151 }
152
153 @PublishedApi
154 internal open class CoroutineTraceName(internal val name: String?) : CoroutineContext.Element {
155 companion object Key : CoroutineContext.Key<CoroutineTraceName>
156
157 override val key: CoroutineContext.Key<*>
158 get() = Key
159
160 @OptIn(ExperimentalStdlibApi::class)
getnull161 override fun <E : CoroutineContext.Element> get(key: CoroutineContext.Key<E>): E? =
162 getPolymorphicElement(key)
163
164 @OptIn(ExperimentalStdlibApi::class)
165 override fun minusKey(key: CoroutineContext.Key<*>): CoroutineContext = minusPolymorphicKey(key)
166
167 @Deprecated(
168 message =
169 """
170 Operator `+` on two BaseTraceElement objects is meaningless. If used, the context element
171 to the right of `+` would simply replace the element to the left. To properly use
172 `BaseTraceElement`, `TraceContextElement` should be used when creating a top-level
173 `CoroutineScope` and `CoroutineTraceName` should be passed to the child context that is
174 under construction.
175 """,
176 level = DeprecationLevel.ERROR,
177 )
178 operator fun plus(other: CoroutineTraceName): CoroutineTraceName {
179 return other
180 }
181
182 @Deprecated(
183 message =
184 """
185 Operator `+` on two BaseTraceElement objects is meaningless. If used, the context element
186 to the right of `+` would simply replace the element to the left. To properly use
187 `BaseTraceElement`, `TraceContextElement` should be used when creating a top-level
188 `CoroutineScope` and `CoroutineTraceName` should be passed to the child context that is
189 under construction.
190 """,
191 level = DeprecationLevel.ERROR,
192 )
plusnull193 operator fun plus(other: TraceContextElement): TraceContextElement {
194 return other
195 }
196 }
197
nextRandomIntnull198 private fun nextRandomInt(): Int = ThreadLocalRandom.current().nextInt(1, Int.MAX_VALUE)
199
200 /**
201 * Used for tracking parent-child relationship of coroutines and persisting [TraceData] when
202 * coroutines are suspended and resumed.
203 *
204 * This is internal machinery for [traceCoroutine] and should not be used directly.
205 *
206 * @param name The name of the current coroutine. Since this should only be installed on top-level
207 * coroutines, this should be the name of the root [CoroutineScope].
208 * @property contextTraceData [TraceData] to be saved to thread-local storage.
209 * @property config Configuration parameters
210 * @param parentId The ID of the parent coroutine, as defined in [BaseTraceElement]
211 * @param inheritedTracePrefix Prefix containing metadata for parent scopes. Each child is separated
212 * by a `:` and prefixed by a counter indicating the ordinal of this child relative to its
213 * siblings. Thus, the prefix such as `root-name:3^child-name` would indicate this is the 3rd
214 * child (of any name) to be started on `root-scope`. If the child has no name, an empty string
215 * would be used instead: `root-scope:3^`
216 * @param coroutineDepth How deep the coroutine is relative to the top-level [CoroutineScope]
217 * containing the original [TraceContextElement] from which this [TraceContextElement] was copied.
218 * If -1, counting depth is disabled
219 * @see createCoroutineTracingContext
220 * @see nameCoroutine
221 * @see traceCoroutine
222 */
223 @SuppressLint("UnclosedTrace")
224 @OptIn(DelicateCoroutinesApi::class, ExperimentalCoroutinesApi::class)
225 internal class TraceContextElement(
226 name: String,
227 private val isRoot: Boolean,
228 countContinuations: Boolean,
229 private val walkStackForDefaultNames: Boolean,
230 private val shouldIgnoreClassName: ((String) -> Boolean)?,
231 parentId: Int?,
232 inheritedTracePrefix: String?,
233 coroutineDepth: Int,
234 ) : CopyableThreadContextElement<TraceData?>, CoroutineTraceName(name), CoroutineContext.Element {
235 @OptIn(ExperimentalStdlibApi::class)
236 companion object Key :
237 AbstractCoroutineContextKey<CoroutineTraceName, TraceContextElement>(
238 CoroutineTraceName,
239 { it as? TraceContextElement },
240 )
241
242 private val currentId: Int = nextRandomInt()
243 private val nameWithId =
244 "${if (isRoot) "ROOT-" else ""}$name;c=$currentId;p=${parentId ?: "none"}"
245
246 // Don't use Perfetto SDK when inherited trace prefixes are used since it is a feature only
247 // intended for testing, and only the `android.os.Trace` APIs currently have test shadows:
248 private val usePerfettoSdk =
249 android.os.Flags.perfettoSdkTracingV2() && inheritedTracePrefix == null
250
251 private var continuationId = if (usePerfettoSdk) nextRandomInt() else 0
252
253 init {
254 val traceSection = "TCE#init;$nameWithId"
255 debug { traceSection }
256 if (usePerfettoSdk) {
257 PerfettoTrace.begin(PerfettoTraceConfig.COROUTINE_CATEGORY, traceSection).emit()
258 } else {
259 Trace.traceBegin(Trace.TRACE_TAG_APP, traceSection) // begin: "TCE#init"
260 }
261 }
262
263 // Minor perf optimization: no need to create TraceData() for root scopes since all launches
264 // require creation of child via [copyForChild] or [mergeForChild].
265 internal val contextTraceData: TraceData? =
266 if (isRoot) null else TraceData(currentId, strictMode = inheritedTracePrefix != null)
267
268 private var coroutineTraceName: String =
269 if (inheritedTracePrefix == null) {
270 COROUTINE_EXECUTION +
271 nameWithId +
272 (if (coroutineDepth == -1) "" else ";d=$coroutineDepth") +
273 (if (countContinuations) ";n=" else "")
274 } else {
275 "$inheritedTracePrefix$name"
276 }
277
278 private var continuationCount = if (countContinuations) 0 else Int.MIN_VALUE
279 private val childDepth =
280 if (inheritedTracePrefix != null || coroutineDepth == -1) -1 else coroutineDepth + 1
281
282 private val childCoroutineCount = if (inheritedTracePrefix != null) AtomicInteger(0) else null
283
284 private val copyForChildTraceMessage = "TCE#copy;$nameWithId"
285 private val mergeForChildTraceMessage = "TCE#merge;$nameWithId"
286
287 init {
288 if (usePerfettoSdk) {
289 PerfettoTrace.end(PerfettoTraceConfig.COROUTINE_CATEGORY)
290 .setFlow(continuationId.toLong())
291 .emit()
292 } else {
293 Trace.traceEnd(Trace.TRACE_TAG_APP) // end: "TCE#init"
294 }
295 }
296
297 /**
298 * This function is invoked before the coroutine is resumed on the current thread. When a
299 * multi-threaded dispatcher is used, calls to `updateThreadContext` may happen in parallel to
300 * the prior `restoreThreadContext` in the same context. However, calls to `updateThreadContext`
301 * will not run in parallel on the same context.
302 *
303 * ```
304 * Thread #1 | [updateThreadContext]....^ [restoreThreadContext]
305 * --------------------------------------------------------------------------------------------
306 * Thread #2 | [updateThreadContext]...........^[restoreThreadContext]
307 * ```
308 *
309 * (`...` indicate coroutine body is running; whitespace indicates the thread is not scheduled;
310 * `^` is a suspension point)
311 */
312 override fun updateThreadContext(context: CoroutineContext): TraceData? {
313 debug { "TCE#update;$nameWithId" }
314 // Calls to `updateThreadContext` will not happen in parallel on the same context,
315 // and they cannot happen before the prior suspension point. Additionally,
316 // `restoreThreadContext` does not modify `traceData`, so it is safe to iterate over
317 // the collection here:
318 val storage = traceThreadLocal.get() ?: return null
319 val oldState = storage.data
320 if (oldState === contextTraceData) return oldState
321 if (usePerfettoSdk) {
322 PerfettoTrace.begin(
323 PerfettoTraceConfig.COROUTINE_CATEGORY,
324 coroutineTraceName + if (continuationCount < 0) "" else continuationCount,
325 )
326 .setTerminatingFlow(continuationId.toLong())
327 .emit()
328 continuationId = nextRandomInt()
329 } else {
330 Trace.traceBegin(Trace.TRACE_TAG_APP, coroutineTraceName)
331 }
332 if (continuationCount >= 0) continuationCount++
333 storage.updateDataForContinuation(contextTraceData, continuationId)
334 return oldState
335 }
336
337 /**
338 * This function is invoked after the coroutine has suspended on the current thread. When a
339 * multi-threaded dispatcher is used, calls to `restoreThreadContext` may happen in parallel to
340 * the subsequent `updateThreadContext` and `restoreThreadContext` operations. The coroutine
341 * body itself will not run in parallel, but `TraceData` could be modified by a coroutine body
342 * after the suspension point in parallel to `restoreThreadContext` associated with the
343 * coroutine body _prior_ to the suspension point.
344 *
345 * ```
346 * Thread #1 | [updateThreadContext].x..^ [restoreThreadContext]
347 * --------------------------------------------------------------------------------------------
348 * Thread #2 | [updateThreadContext]..x..x.....^[restoreThreadContext]
349 * ```
350 *
351 * OR
352 *
353 * ```
354 * Thread #1 | [update].x..^ [ ... restore ... ] [update].x..^[restore]
355 * --------------------------------------------------------------------------------------------
356 * Thread #2 | [update]...x....x..^[restore]
357 * --------------------------------------------------------------------------------------------
358 * Thread #3 | [ ... update ... ] ...^ [restore]
359 * ```
360 *
361 * (`...` indicate coroutine body is running; whitespace indicates the thread is not scheduled;
362 * `^` is a suspension point; `x` are calls to modify the thread-local trace data)
363 *
364 * ```
365 */
366 override fun restoreThreadContext(context: CoroutineContext, oldState: TraceData?) {
367 debug { "TCE#restore;$nameWithId restoring=${oldState?.currentId}" }
368 // We not use the `TraceData` object here because it may have been modified on another
369 // thread after the last suspension point. This is why we use a [TraceStateHolder]:
370 // so we can end the correct number of trace sections, restoring the thread to its state
371 // prior to the last call to [updateThreadContext].
372 val storage = traceThreadLocal.get() ?: return
373 if (storage.data === oldState) return
374 val contId = storage.restoreDataForSuspension(oldState)
375 if (usePerfettoSdk) {
376 PerfettoTrace.end(PerfettoTraceConfig.COROUTINE_CATEGORY)
377 .setFlow(contId.toLong())
378 .emit()
379 } else {
380 Trace.traceEnd(Trace.TRACE_TAG_APP) // end: coroutineTraceName
381 }
382 }
383
384 override fun copyForChild(): CopyableThreadContextElement<TraceData?> {
385 debug { copyForChildTraceMessage }
386 try {
387 Trace.traceBegin(Trace.TRACE_TAG_APP, copyForChildTraceMessage) // begin: TCE#copy
388 // Root is a special case in which the name is copied to the child by default.
389 // Otherwise, everything launched on a coroutine would have an empty name by default
390 return createChildContext(if (isRoot) name else null)
391 } finally {
392 Trace.traceEnd(Trace.TRACE_TAG_APP) // end: TCE#copy
393 }
394 }
395
396 override fun mergeForChild(overwritingElement: CoroutineContext.Element): CoroutineContext {
397 debug { mergeForChildTraceMessage }
398 try {
399 Trace.traceBegin(Trace.TRACE_TAG_APP, mergeForChildTraceMessage) // begin: TCE#merge
400 return createChildContext(overwritingElement[CoroutineTraceName]?.name)
401 } finally {
402 Trace.traceEnd(Trace.TRACE_TAG_APP) // end: TCE#merge
403 }
404 }
405
406 private fun createChildContext(name: String?): TraceContextElement {
407 return TraceContextElement(
408 name =
409 if (name == null && walkStackForDefaultNames)
410 walkStackForClassName(shouldIgnoreClassName)
411 else name ?: "",
412 isRoot = false,
413 countContinuations = continuationCount >= 0,
414 walkStackForDefaultNames = walkStackForDefaultNames,
415 shouldIgnoreClassName = shouldIgnoreClassName,
416 parentId = currentId,
417 inheritedTracePrefix =
418 if (childCoroutineCount != null) {
419 val childCount = childCoroutineCount.incrementAndGet()
420 "${if (isRoot) "" else "$coroutineTraceName:"}$childCount^"
421 } else null,
422 coroutineDepth = childDepth,
423 )
424 }
425 }
426
427 /**
428 * Get a name for the trace section include the name of the call site.
429 *
430 * @param additionalDropPredicate additional checks for whether class should be ignored
431 */
walkStackForClassNamenull432 private fun walkStackForClassName(additionalDropPredicate: ((String) -> Boolean)? = null): String {
433 Trace.traceBegin(Trace.TRACE_TAG_APP, "walkStackForClassName")
434 try {
435 var frame = ""
436 StackWalker.getInstance().walk { s: Stream<StackFrame> ->
437 s.dropWhile { f: StackFrame ->
438 val className = f.className
439 className.startsWith("kotlin") ||
440 className.startsWith("com.android.app.tracing.") ||
441 (additionalDropPredicate != null && additionalDropPredicate(className))
442 }
443 .findFirst()
444 .ifPresent { frame = it.className.substringAfterLast(".") + "." + it.methodName }
445 }
446 return frame
447 } catch (e: Exception) {
448 if (DEBUG) Log.e(TAG, "Error walking stack to infer a trace name", e)
449 return ""
450 } finally {
451 Trace.traceEnd(Trace.TRACE_TAG_APP)
452 }
453 }
454
455 private const val UNEXPECTED_TRACE_DATA_ERROR_MESSAGE =
456 "Overwriting context element with non-empty trace data. There should only be one " +
457 "TraceContextElement per coroutine, and it should be installed in the root scope. "
458
459 @PublishedApi internal const val COROUTINE_EXECUTION: String = "coroutine execution;"
460
461 @PublishedApi internal const val TAG: String = "CoroutineTracing"
462
463 @PublishedApi internal const val DEBUG: Boolean = false
464
465 @OptIn(ExperimentalContracts::class)
debugnull466 private inline fun debug(message: () -> String) {
467 contract { callsInPlace(message, InvocationKind.AT_MOST_ONCE) }
468 if (DEBUG) {
469 val msg = message()
470 Trace.instant(Trace.TRACE_TAG_APP, msg)
471 Log.d(TAG, msg)
472 }
473 }
474