• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
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