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