Loading tracinglib/core/src/coroutines/CoroutineTracing.kt +4 −4 Original line number Diff line number Diff line Loading @@ -223,10 +223,10 @@ public inline fun <T, R> R.traceCoroutine(crossinline spanName: () -> String, bl // tracing is not active (i.e. when TRACE_TAG_APP is disabled). Otherwise, when the // coroutine resumes when tracing is active, we won't know its name. try { if (Flags.coroutineTracing()) traceThreadLocal.get()?.beginSpan(spanName()) if (Flags.coroutineTracing()) traceThreadLocal.get()?.beginCoroutineTrace(spanName()) return block() } finally { if (Flags.coroutineTracing()) traceThreadLocal.get()?.endSpan() if (Flags.coroutineTracing()) traceThreadLocal.get()?.endCoroutineTrace() } } Loading @@ -239,10 +239,10 @@ public inline fun <T> traceCoroutine(crossinline spanName: () -> String, block: // tracing is not active (i.e. when TRACE_TAG_APP is disabled). Otherwise, when the // coroutine resumes when tracing is active, we won't know its name. try { if (Flags.coroutineTracing()) traceThreadLocal.get()?.beginSpan(spanName()) if (Flags.coroutineTracing()) traceThreadLocal.get()?.beginCoroutineTrace(spanName()) return block() } finally { if (Flags.coroutineTracing()) traceThreadLocal.get()?.endSpan() if (Flags.coroutineTracing()) traceThreadLocal.get()?.endCoroutineTrace() } } Loading tracinglib/core/src/coroutines/TraceContextElement.kt +88 −45 Original line number Diff line number Diff line Loading @@ -17,6 +17,7 @@ package com.android.app.tracing.coroutines import android.annotation.SuppressLint import android.os.PerfettoTrace import android.os.SystemProperties import android.os.Trace import android.util.Log Loading @@ -38,9 +39,6 @@ import kotlinx.coroutines.CoroutineScope import kotlinx.coroutines.DelicateCoroutinesApi import kotlinx.coroutines.ExperimentalCoroutinesApi /** Use a final subclass to avoid virtual calls (b/316642146). */ @PublishedApi internal class TraceDataThreadLocal : ThreadLocal<TraceData?>() /** * Thread-local storage for tracking open trace sections in the current coroutine context; it should * only be used when paired with a [TraceContextElement]. Loading @@ -54,12 +52,20 @@ import kotlinx.coroutines.ExperimentalCoroutinesApi */ @PublishedApi internal val traceThreadLocal: TraceDataThreadLocal = TraceDataThreadLocal() private val alwaysEnableStackWalker = internal object DebugSysProps { @JvmField val alwaysEnableStackWalker = SystemProperties.getBoolean("debug.coroutine_tracing.walk_stack_override", false) private val alwaysEnableContinuationCounting = @JvmField val alwaysEnableContinuationCounting = SystemProperties.getBoolean("debug.coroutine_tracing.count_continuations_override", false) @JvmField val UsePerfettoSdk = SystemProperties.getBoolean("debug.coroutine_tracing.use_perfetto_sdk", false) } /** * Returns a new [TraceContextElement] (or [EmptyCoroutineContext] if `coroutine_tracing` feature is * flagged off). This context should only be installed on root coroutines (e.g. when constructing a Loading Loading @@ -124,8 +130,9 @@ public fun createCoroutineTracingContext( name = name, isRoot = true, countContinuations = !testMode && (countContinuations || alwaysEnableContinuationCounting), walkStackForDefaultNames = walkStackForDefaultNames || alwaysEnableStackWalker, !testMode && (countContinuations || DebugSysProps.alwaysEnableContinuationCounting), walkStackForDefaultNames = walkStackForDefaultNames || DebugSysProps.alwaysEnableStackWalker, shouldIgnoreClassName = shouldIgnoreClassName, parentId = null, inheritedTracePrefix = if (testMode) "" else null, Loading Loading @@ -162,6 +169,17 @@ public inline fun nameCoroutine(name: () -> String): CoroutineContext { return if (Flags.coroutineTracing()) CoroutineTraceName(name()) else EmptyCoroutineContext } private object PerfettoTraceConfig { // cc = coroutine continuations @JvmField val COROUTINE_CATEGORY: PerfettoTrace.Category = PerfettoTrace.Category("cc") init { if (DebugSysProps.UsePerfettoSdk) { COROUTINE_CATEGORY.register() } } } @PublishedApi internal open class CoroutineTraceName(internal val name: String?) : CoroutineContext.Element { companion object Key : CoroutineContext.Key<CoroutineTraceName> Loading Loading @@ -207,6 +225,8 @@ internal open class CoroutineTraceName(internal val name: String?) : CoroutineCo } } private fun nextRandomInt(): Int = ThreadLocalRandom.current().nextInt(1, Int.MAX_VALUE) /** * Used for tracking parent-child relationship of coroutines and persisting [TraceData] when * coroutines are suspended and resumed. Loading @@ -230,11 +250,12 @@ internal open class CoroutineTraceName(internal val name: String?) : CoroutineCo * @see nameCoroutine * @see traceCoroutine */ @SuppressLint("UnclosedTrace") @OptIn(DelicateCoroutinesApi::class, ExperimentalCoroutinesApi::class) internal class TraceContextElement( name: String, private val isRoot: Boolean, private val countContinuations: Boolean, countContinuations: Boolean, private val walkStackForDefaultNames: Boolean, private val shouldIgnoreClassName: ((String) -> Boolean)?, parentId: Int?, Loading @@ -248,15 +269,24 @@ internal class TraceContextElement( { it as? TraceContextElement }, ) private val currentId: Int = ThreadLocalRandom.current().nextInt(1, Int.MAX_VALUE) private val currentId: Int = nextRandomInt() private val nameWithId = "${if (isRoot) "ROOT-" else ""}$name;c=$currentId;p=${parentId ?: "none"}" // Don't use Perfetto SDK when inherited trace prefixes are used since it is a feature only // intended for testing, and only the `android.os.Trace` APIs currently have test shadows: private val usePerfettoSdk = DebugSysProps.UsePerfettoSdk && inheritedTracePrefix == null private var continuationId = if (usePerfettoSdk) nextRandomInt() else 0 init { val traceSection = "TCE#init;$nameWithId" debug { traceSection } Trace.traceBegin(Trace.TRACE_TAG_APP, traceSection) if (usePerfettoSdk) { PerfettoTrace.begin(PerfettoTraceConfig.COROUTINE_CATEGORY, traceSection).emit() } else { Trace.traceBegin(Trace.TRACE_TAG_APP, traceSection) // begin: "TCE#init" } } // Minor perf optimization: no need to create TraceData() for root scopes since all launches Loading @@ -266,12 +296,15 @@ internal class TraceContextElement( private var coroutineTraceName: String = if (inheritedTracePrefix == null) { "coroutine execution;$nameWithId${if (coroutineDepth == -1) "" else ";d=$coroutineDepth"}" COROUTINE_EXECUTION + nameWithId + (if (coroutineDepth == -1) "" else ";d=$coroutineDepth") + (if (countContinuations) ";n=" else "") } else { "$inheritedTracePrefix$name" } private var continuationCount = 0 private var continuationCount = if (countContinuations) 0 else Int.MIN_VALUE private val childDepth = if (inheritedTracePrefix != null || coroutineDepth == -1) -1 else coroutineDepth + 1 Loading @@ -281,8 +314,12 @@ internal class TraceContextElement( private val mergeForChildTraceMessage = "TCE#merge;$nameWithId" init { if (usePerfettoSdk) { PerfettoTrace.end(PerfettoTraceConfig.COROUTINE_CATEGORY).addFlow(continuationId).emit() } else { Trace.traceEnd(Trace.TRACE_TAG_APP) // end: "TCE#init" } } /** * This function is invoked before the coroutine is resumed on the current thread. When a Loading @@ -299,25 +336,28 @@ internal class TraceContextElement( * (`...` indicate coroutine body is running; whitespace indicates the thread is not scheduled; * `^` is a suspension point) */ @SuppressLint("UnclosedTrace") override fun updateThreadContext(context: CoroutineContext): TraceData? { val oldState = traceThreadLocal.get() debug { "TCE#update;$nameWithId oldState=${oldState?.currentId}" } if (oldState !== contextTraceData) { traceThreadLocal.set(contextTraceData) if (Trace.isTagEnabled(Trace.TRACE_TAG_APP)) { Trace.traceBegin( Trace.TRACE_TAG_APP, if (countContinuations) "$coroutineTraceName;n=${continuationCount++}" else coroutineTraceName, ) debug { "TCE#update;$nameWithId" } // Calls to `updateThreadContext` will not happen in parallel on the same context, // and they cannot happen before the prior suspension point. Additionally, // `restoreThreadContext` does not modify `traceData`, so it is safe to iterate over // the collection here: contextTraceData?.beginAllOnThread() } val storage = traceThreadLocal.get() ?: return null val oldState = storage.data if (oldState === contextTraceData) return oldState if (usePerfettoSdk) { PerfettoTrace.begin( PerfettoTraceConfig.COROUTINE_CATEGORY, coroutineTraceName + if (continuationCount < 0) "" else continuationCount, ) .addTerminatingFlow(continuationId) .emit() continuationId = nextRandomInt() } else { Trace.traceBegin(Trace.TRACE_TAG_APP, coroutineTraceName) } if (continuationCount >= 0) continuationCount++ storage.updateDataForContinuation(contextTraceData, continuationId) return oldState } Loading @@ -342,7 +382,7 @@ internal class TraceContextElement( * -------------------------------------------------------------------------------------------- * Thread #2 | [update]...x....x..^[restore] * -------------------------------------------------------------------------------------------- * Thread #3 | [ ... update ... ] ....^ [restore] * Thread #3 | [ ... update ... ] ...^ [restore] * ``` * * (`...` indicate coroutine body is running; whitespace indicates the thread is not scheduled; Loading @@ -356,34 +396,35 @@ internal class TraceContextElement( // thread after the last suspension point. This is why we use a [TraceStateHolder]: // so we can end the correct number of trace sections, restoring the thread to its state // prior to the last call to [updateThreadContext]. if (oldState !== traceThreadLocal.get()) { if (Trace.isTagEnabled(Trace.TRACE_TAG_APP)) { contextTraceData?.endAllOnThread() val storage = traceThreadLocal.get() ?: return if (storage.data === oldState) return val contId = storage.restoreDataForSuspension(oldState) if (usePerfettoSdk) { PerfettoTrace.end(PerfettoTraceConfig.COROUTINE_CATEGORY).addFlow(contId).emit() } else { Trace.traceEnd(Trace.TRACE_TAG_APP) // end: coroutineTraceName } traceThreadLocal.set(oldState) } } override fun copyForChild(): CopyableThreadContextElement<TraceData?> { debug { copyForChildTraceMessage } try { Trace.traceBegin(Trace.TRACE_TAG_APP, copyForChildTraceMessage) Trace.traceBegin(Trace.TRACE_TAG_APP, copyForChildTraceMessage) // begin: TCE#copy // Root is a special case in which the name is copied to the child by default. // Otherwise, everything launched on a coroutine would have an empty name by default return createChildContext(if (isRoot) name else null) } finally { Trace.traceEnd(Trace.TRACE_TAG_APP) // end: copyForChildTraceMessage Trace.traceEnd(Trace.TRACE_TAG_APP) // end: TCE#copy } } override fun mergeForChild(overwritingElement: CoroutineContext.Element): CoroutineContext { debug { mergeForChildTraceMessage } try { Trace.traceBegin(Trace.TRACE_TAG_APP, mergeForChildTraceMessage) Trace.traceBegin(Trace.TRACE_TAG_APP, mergeForChildTraceMessage) // begin: TCE#merge return createChildContext(overwritingElement[CoroutineTraceName]?.name) } finally { Trace.traceEnd(Trace.TRACE_TAG_APP) // end: mergeForChildTraceMessage Trace.traceEnd(Trace.TRACE_TAG_APP) // end: TCE#merge } } Loading @@ -394,7 +435,7 @@ internal class TraceContextElement( walkStackForClassName(shouldIgnoreClassName) else name ?: "", isRoot = false, countContinuations = countContinuations, countContinuations = continuationCount >= 0, walkStackForDefaultNames = walkStackForDefaultNames, shouldIgnoreClassName = shouldIgnoreClassName, parentId = currentId, Loading Loading @@ -440,6 +481,8 @@ private const val UNEXPECTED_TRACE_DATA_ERROR_MESSAGE = "Overwriting context element with non-empty trace data. There should only be one " + "TraceContextElement per coroutine, and it should be installed in the root scope. " @PublishedApi internal const val COROUTINE_EXECUTION: String = "coroutine execution;" @PublishedApi internal const val TAG: String = "CoroutineTracing" @PublishedApi internal const val DEBUG: Boolean = false Loading tracinglib/core/src/coroutines/TraceData.kt +163 −36 Original line number Diff line number Diff line Loading @@ -14,12 +14,18 @@ * limitations under the License. */ @file:OptIn(ExperimentalContracts::class) package com.android.app.tracing.coroutines import android.os.Trace import com.android.app.tracing.beginSlice import com.android.app.tracing.endSlice import com.android.systemui.Flags import java.util.ArrayDeque import kotlin.contracts.ExperimentalContracts import kotlin.math.max import kotlinx.coroutines.CoroutineStart.UNDISPATCHED /** * Represents a section of code executing in a coroutine. This may be split up into multiple slices Loading @@ -29,23 +35,138 @@ import java.util.ArrayDeque */ private typealias TraceSection = String private class MutableInt(var value: Int) /** Use a final subclass to avoid virtual calls (b/316642146). */ @PublishedApi internal class TraceDataThreadLocal : ThreadLocal<TraceStorage?>() { override fun initialValue(): TraceStorage? { return if (Flags.coroutineTracing()) { TraceStorage(null) } else { null } } } private class ThreadLocalInt : ThreadLocal<MutableInt>() { override fun initialValue(): MutableInt { return MutableInt(0) /** * There should only be one instance of this class per thread. * * @param openSliceCount ThreadLocal counter for how many open trace sections there are on the * current thread. This is needed because it is possible that on a multi-threaded dispatcher, one * of the threads could be slow, and [TraceContextElement.restoreThreadContext] might be invoked * _after_ the coroutine has already resumed and modified [TraceData] - either adding or removing * trace sections and changing the count. If we did not store this thread-locally, then we would * incorrectly end too many or too few trace sections. */ @PublishedApi internal class TraceStorage(internal var data: TraceData?) { /** * Counter for tracking which index to use in the [continuationIds] and [openSliceCount] arrays. * `contIndex` is used to keep track of the stack used for managing tracing state when * coroutines are resumed and suspended in a nested way. * * `-1` indicates no coroutine is currently running * * `0` indicates one coroutine is running * * `>1` indicates the current coroutine is resumed inside another coroutine, e.g. due to an * unconfined dispatcher or [UNDISPATCHED] launch. */ internal var contIndex = -1 internal lateinit var continuationIds: IntArray private lateinit var debugCounterTrack: String init { if (DebugSysProps.UsePerfettoSdk) { continuationIds = IntArray(INITIAL_THREAD_LOCAL_STACK_SIZE) } if (DEBUG) { debugCounterTrack = "TCE#${Thread.currentThread().threadId()}" } } /** * Count of slices opened on the current thread due to current [TraceData] that must be closed * when it is removed. If another [data] overwrites the current one, all trace sections due to * current [data] must be closed. The overwriting [data] will handle updating itself when * [TraceContextElement.updateThreadContext] is called for it. * * Expected nesting should never exceed 255, so use a [ByteArray]. If nesting _does_ exceed 255, * it indicates there is already something very wrong with the trace, so we will not waste CPU * cycles error checking. */ internal var openSliceCount = ByteArray(INITIAL_THREAD_LOCAL_STACK_SIZE) /** * ThreadLocal counter for how many open trace sections there are. This is needed because it is * possible that on a multi-threaded dispatcher, one of the threads could be slow, and * [TraceContextElement.restoreThreadContext] might be invoked _after_ the coroutine has already * resumed and modified [TraceData] - either adding or removing trace sections and changing the * count. If we did not store this thread-locally, then we would incorrectly end too many or too few * trace sections. * Adds a new trace section to the current trace data. The slice will be traced on the current * thread immediately. This slice will not propagate to parent coroutines, or to child * coroutines that have already started. */ private val openSliceCount = ThreadLocalInt() @PublishedApi internal fun beginCoroutineTrace(name: String) { val data = data ?: return data.beginSpan(name) if (0 <= contIndex && contIndex < openSliceCount.size) { openSliceCount[contIndex]++ } } /** * Ends the trace section and validates it corresponds with an earlier call to * [beginCoroutineTrace]. The trace slice will immediately be removed from the current thread. * This information will not propagate to parent coroutines, or to child coroutines that have * already started. * * @return true if span was ended, `false` if not */ @PublishedApi internal fun endCoroutineTrace() { if (data?.endSpan() == true && 0 <= contIndex && contIndex < openSliceCount.size) { openSliceCount[contIndex]-- } } /** Update [data] for continuation */ fun updateDataForContinuation(contextTraceData: TraceData?, contId: Int) { data = contextTraceData val n = ++contIndex if (DEBUG) { Trace.traceCounter(Trace.TRACE_TAG_APP, debugCounterTrack, n) } if (n < 0 || MAX_THREAD_LOCAL_STACK_SIZE <= n) return // fail-safe var size = openSliceCount.size if (n >= size) { size = max(2 * size, MAX_THREAD_LOCAL_STACK_SIZE) openSliceCount = openSliceCount.copyInto(ByteArray(size)) if (::continuationIds.isInitialized) { continuationIds = continuationIds.copyInto(IntArray(size)) } } openSliceCount[n] = data?.beginAllOnThread() ?: 0 if (::continuationIds.isInitialized && 0 < contId) { continuationIds[n] = contId } } /** Update [data] for suspension */ fun restoreDataForSuspension(oldState: TraceData?): Int { data = oldState val n = contIndex-- if (DEBUG) { Trace.traceCounter(Trace.TRACE_TAG_APP, debugCounterTrack, n) } if (n < 0 || MAX_THREAD_LOCAL_STACK_SIZE <= n) return 0 // fail-safe if (Trace.isTagEnabled(Trace.TRACE_TAG_APP)) { val lastState = openSliceCount[n] var i = 0 while (i < lastState) { endSlice() i++ } } return if (::continuationIds.isInitialized && n < continuationIds.size) continuationIds[n] else 0 } } /** * Used for storing trace sections so that they can be added and removed from the currently running Loading @@ -62,27 +183,24 @@ internal class TraceData(internal val currentId: Int, private val strictMode: Bo internal lateinit var slices: ArrayDeque<TraceSection> /** Adds current trace slices back to the current thread. Called when coroutine is resumed. */ internal fun beginAllOnThread() { /** * Adds current trace slices back to the current thread. Called when coroutine is resumed. * * @return number of new trace sections started */ internal fun beginAllOnThread(): Byte { if (Trace.isTagEnabled(Trace.TRACE_TAG_APP)) { strictModeCheck() if (::slices.isInitialized) { slices.descendingIterator().forEach { sectionName -> beginSlice(sectionName) } openSliceCount.get()!!.value = slices.size var count: Byte = 0 slices.descendingIterator().forEach { sectionName -> beginSlice(sectionName) count++ } return count } } /** * Removes all current trace slices from the current thread. Called when coroutine is suspended. */ internal fun endAllOnThread() { if (Trace.isTagEnabled(Trace.TRACE_TAG_APP)) { strictModeCheck() val sliceCount = openSliceCount.get()!! repeat(sliceCount.value) { endSlice() } sliceCount.value = 0 } return 0 } /** Loading @@ -91,14 +209,12 @@ internal class TraceData(internal val currentId: Int, private val strictMode: Bo * coroutines, or to child coroutines that have already started. The unique ID is used to verify * that the [endSpan] is corresponds to a [beginSpan]. */ @PublishedApi internal fun beginSpan(name: String) { strictModeCheck() if (!::slices.isInitialized) { slices = ArrayDeque<TraceSection>(4) } slices.push(name) openSliceCount.get()!!.value = slices.size beginSlice(name) } Loading @@ -106,18 +222,20 @@ internal class TraceData(internal val currentId: Int, private val strictMode: Bo * Ends the trace section and validates it corresponds with an earlier call to [beginSpan]. The * trace slice will immediately be removed from the current thread. This information will not * propagate to parent coroutines, or to child coroutines that have already started. * * @return `true` if [endSlice] was called, `false` otherwise */ @PublishedApi internal fun endSpan() { internal fun endSpan(): Boolean { strictModeCheck() // Should never happen, but we should be defensive rather than crash the whole application if (::slices.isInitialized && slices.size > 0) { if (::slices.isInitialized && !slices.isEmpty()) { slices.pop() openSliceCount.get()!!.value = slices.size endSlice() return true } else if (strictMode) { throw IllegalStateException(INVALID_SPAN_END_CALL_ERROR_MESSAGE) } return false } public override fun toString(): String = Loading @@ -126,16 +244,25 @@ internal class TraceData(internal val currentId: Int, private val strictMode: Bo "{${slices.joinToString(separator = "\", \"", prefix = "\"", postfix = "\"")}}" } else { "{<uninitialized>}" } } + "@${hashCode()}" } else super.toString() private fun strictModeCheck() { if (strictMode && traceThreadLocal.get() !== this) { if (strictMode && traceThreadLocal.get()?.data !== this) { throw ConcurrentModificationException(STRICT_MODE_ERROR_MESSAGE) } } } private const val INITIAL_THREAD_LOCAL_STACK_SIZE = 4 /** * The maximum allowed stack size for coroutine re-entry. Anything above this will cause malformed * traces. It should be set to a high number that should never happen, meaning if it were to occur, * there is likely an underlying bug. */ private const val MAX_THREAD_LOCAL_STACK_SIZE = 512 private const val INVALID_SPAN_END_CALL_ERROR_MESSAGE = "TraceData#endSpan called when there were no active trace sections in its scope." Loading tracinglib/demo/src/experiments/LaunchNested.kt +16 −15 Original line number Diff line number Diff line Loading @@ -15,32 +15,33 @@ */ package com.example.tracing.demo.experiments import com.android.app.tracing.coroutines.launchTraced as launch import com.android.app.tracing.coroutines.launchTraced import com.android.app.tracing.coroutines.traceCoroutine import com.example.tracing.demo.FixedThread1 import com.example.tracing.demo.FixedThread2 import com.example.tracing.demo.FixedThread3 import javax.inject.Inject import javax.inject.Singleton import kotlinx.coroutines.CoroutineDispatcher import kotlinx.coroutines.CoroutineScope import kotlinx.coroutines.CoroutineStart import kotlinx.coroutines.coroutineScope import kotlinx.coroutines.delay import kotlinx.coroutines.withContext @Singleton class LaunchNested @Inject constructor( @FixedThread1 private var dispatcher1: CoroutineDispatcher, @FixedThread2 private var dispatcher2: CoroutineDispatcher, @FixedThread3 private val dispatcher3: CoroutineDispatcher, ) : TracedExperiment() { class LaunchNested @Inject constructor(@FixedThread1 private var dispatcher1: CoroutineDispatcher) : TracedExperiment() { override val description: String = "launch{launch{launch{launch{}}}}" override suspend fun runExperiment(): Unit = coroutineScope { launch("launch(thread1)", dispatcher1) { forceSuspend("111", 5) launch("launch(thread2)", dispatcher2) { forceSuspend("222", 5) launch("launch(thread3)", dispatcher3) { forceSuspend("333", 5) } fun CoroutineScope.recursivelyLaunch(n: Int) { if (n == 400) return launchTraced("launch#$n", start = CoroutineStart.UNDISPATCHED) { traceCoroutine("trace-span") { recursivelyLaunch(n + 1) delay(1) } } } withContext(dispatcher1) { recursivelyLaunch(0) } } } tracinglib/demo/src/experiments/LaunchStressTest.kt +33 −5 File changed.Preview size limit exceeded, changes collapsed. Show changes Loading
tracinglib/core/src/coroutines/CoroutineTracing.kt +4 −4 Original line number Diff line number Diff line Loading @@ -223,10 +223,10 @@ public inline fun <T, R> R.traceCoroutine(crossinline spanName: () -> String, bl // tracing is not active (i.e. when TRACE_TAG_APP is disabled). Otherwise, when the // coroutine resumes when tracing is active, we won't know its name. try { if (Flags.coroutineTracing()) traceThreadLocal.get()?.beginSpan(spanName()) if (Flags.coroutineTracing()) traceThreadLocal.get()?.beginCoroutineTrace(spanName()) return block() } finally { if (Flags.coroutineTracing()) traceThreadLocal.get()?.endSpan() if (Flags.coroutineTracing()) traceThreadLocal.get()?.endCoroutineTrace() } } Loading @@ -239,10 +239,10 @@ public inline fun <T> traceCoroutine(crossinline spanName: () -> String, block: // tracing is not active (i.e. when TRACE_TAG_APP is disabled). Otherwise, when the // coroutine resumes when tracing is active, we won't know its name. try { if (Flags.coroutineTracing()) traceThreadLocal.get()?.beginSpan(spanName()) if (Flags.coroutineTracing()) traceThreadLocal.get()?.beginCoroutineTrace(spanName()) return block() } finally { if (Flags.coroutineTracing()) traceThreadLocal.get()?.endSpan() if (Flags.coroutineTracing()) traceThreadLocal.get()?.endCoroutineTrace() } } Loading
tracinglib/core/src/coroutines/TraceContextElement.kt +88 −45 Original line number Diff line number Diff line Loading @@ -17,6 +17,7 @@ package com.android.app.tracing.coroutines import android.annotation.SuppressLint import android.os.PerfettoTrace import android.os.SystemProperties import android.os.Trace import android.util.Log Loading @@ -38,9 +39,6 @@ import kotlinx.coroutines.CoroutineScope import kotlinx.coroutines.DelicateCoroutinesApi import kotlinx.coroutines.ExperimentalCoroutinesApi /** Use a final subclass to avoid virtual calls (b/316642146). */ @PublishedApi internal class TraceDataThreadLocal : ThreadLocal<TraceData?>() /** * Thread-local storage for tracking open trace sections in the current coroutine context; it should * only be used when paired with a [TraceContextElement]. Loading @@ -54,12 +52,20 @@ import kotlinx.coroutines.ExperimentalCoroutinesApi */ @PublishedApi internal val traceThreadLocal: TraceDataThreadLocal = TraceDataThreadLocal() private val alwaysEnableStackWalker = internal object DebugSysProps { @JvmField val alwaysEnableStackWalker = SystemProperties.getBoolean("debug.coroutine_tracing.walk_stack_override", false) private val alwaysEnableContinuationCounting = @JvmField val alwaysEnableContinuationCounting = SystemProperties.getBoolean("debug.coroutine_tracing.count_continuations_override", false) @JvmField val UsePerfettoSdk = SystemProperties.getBoolean("debug.coroutine_tracing.use_perfetto_sdk", false) } /** * Returns a new [TraceContextElement] (or [EmptyCoroutineContext] if `coroutine_tracing` feature is * flagged off). This context should only be installed on root coroutines (e.g. when constructing a Loading Loading @@ -124,8 +130,9 @@ public fun createCoroutineTracingContext( name = name, isRoot = true, countContinuations = !testMode && (countContinuations || alwaysEnableContinuationCounting), walkStackForDefaultNames = walkStackForDefaultNames || alwaysEnableStackWalker, !testMode && (countContinuations || DebugSysProps.alwaysEnableContinuationCounting), walkStackForDefaultNames = walkStackForDefaultNames || DebugSysProps.alwaysEnableStackWalker, shouldIgnoreClassName = shouldIgnoreClassName, parentId = null, inheritedTracePrefix = if (testMode) "" else null, Loading Loading @@ -162,6 +169,17 @@ public inline fun nameCoroutine(name: () -> String): CoroutineContext { return if (Flags.coroutineTracing()) CoroutineTraceName(name()) else EmptyCoroutineContext } private object PerfettoTraceConfig { // cc = coroutine continuations @JvmField val COROUTINE_CATEGORY: PerfettoTrace.Category = PerfettoTrace.Category("cc") init { if (DebugSysProps.UsePerfettoSdk) { COROUTINE_CATEGORY.register() } } } @PublishedApi internal open class CoroutineTraceName(internal val name: String?) : CoroutineContext.Element { companion object Key : CoroutineContext.Key<CoroutineTraceName> Loading Loading @@ -207,6 +225,8 @@ internal open class CoroutineTraceName(internal val name: String?) : CoroutineCo } } private fun nextRandomInt(): Int = ThreadLocalRandom.current().nextInt(1, Int.MAX_VALUE) /** * Used for tracking parent-child relationship of coroutines and persisting [TraceData] when * coroutines are suspended and resumed. Loading @@ -230,11 +250,12 @@ internal open class CoroutineTraceName(internal val name: String?) : CoroutineCo * @see nameCoroutine * @see traceCoroutine */ @SuppressLint("UnclosedTrace") @OptIn(DelicateCoroutinesApi::class, ExperimentalCoroutinesApi::class) internal class TraceContextElement( name: String, private val isRoot: Boolean, private val countContinuations: Boolean, countContinuations: Boolean, private val walkStackForDefaultNames: Boolean, private val shouldIgnoreClassName: ((String) -> Boolean)?, parentId: Int?, Loading @@ -248,15 +269,24 @@ internal class TraceContextElement( { it as? TraceContextElement }, ) private val currentId: Int = ThreadLocalRandom.current().nextInt(1, Int.MAX_VALUE) private val currentId: Int = nextRandomInt() private val nameWithId = "${if (isRoot) "ROOT-" else ""}$name;c=$currentId;p=${parentId ?: "none"}" // Don't use Perfetto SDK when inherited trace prefixes are used since it is a feature only // intended for testing, and only the `android.os.Trace` APIs currently have test shadows: private val usePerfettoSdk = DebugSysProps.UsePerfettoSdk && inheritedTracePrefix == null private var continuationId = if (usePerfettoSdk) nextRandomInt() else 0 init { val traceSection = "TCE#init;$nameWithId" debug { traceSection } Trace.traceBegin(Trace.TRACE_TAG_APP, traceSection) if (usePerfettoSdk) { PerfettoTrace.begin(PerfettoTraceConfig.COROUTINE_CATEGORY, traceSection).emit() } else { Trace.traceBegin(Trace.TRACE_TAG_APP, traceSection) // begin: "TCE#init" } } // Minor perf optimization: no need to create TraceData() for root scopes since all launches Loading @@ -266,12 +296,15 @@ internal class TraceContextElement( private var coroutineTraceName: String = if (inheritedTracePrefix == null) { "coroutine execution;$nameWithId${if (coroutineDepth == -1) "" else ";d=$coroutineDepth"}" COROUTINE_EXECUTION + nameWithId + (if (coroutineDepth == -1) "" else ";d=$coroutineDepth") + (if (countContinuations) ";n=" else "") } else { "$inheritedTracePrefix$name" } private var continuationCount = 0 private var continuationCount = if (countContinuations) 0 else Int.MIN_VALUE private val childDepth = if (inheritedTracePrefix != null || coroutineDepth == -1) -1 else coroutineDepth + 1 Loading @@ -281,8 +314,12 @@ internal class TraceContextElement( private val mergeForChildTraceMessage = "TCE#merge;$nameWithId" init { if (usePerfettoSdk) { PerfettoTrace.end(PerfettoTraceConfig.COROUTINE_CATEGORY).addFlow(continuationId).emit() } else { Trace.traceEnd(Trace.TRACE_TAG_APP) // end: "TCE#init" } } /** * This function is invoked before the coroutine is resumed on the current thread. When a Loading @@ -299,25 +336,28 @@ internal class TraceContextElement( * (`...` indicate coroutine body is running; whitespace indicates the thread is not scheduled; * `^` is a suspension point) */ @SuppressLint("UnclosedTrace") override fun updateThreadContext(context: CoroutineContext): TraceData? { val oldState = traceThreadLocal.get() debug { "TCE#update;$nameWithId oldState=${oldState?.currentId}" } if (oldState !== contextTraceData) { traceThreadLocal.set(contextTraceData) if (Trace.isTagEnabled(Trace.TRACE_TAG_APP)) { Trace.traceBegin( Trace.TRACE_TAG_APP, if (countContinuations) "$coroutineTraceName;n=${continuationCount++}" else coroutineTraceName, ) debug { "TCE#update;$nameWithId" } // Calls to `updateThreadContext` will not happen in parallel on the same context, // and they cannot happen before the prior suspension point. Additionally, // `restoreThreadContext` does not modify `traceData`, so it is safe to iterate over // the collection here: contextTraceData?.beginAllOnThread() } val storage = traceThreadLocal.get() ?: return null val oldState = storage.data if (oldState === contextTraceData) return oldState if (usePerfettoSdk) { PerfettoTrace.begin( PerfettoTraceConfig.COROUTINE_CATEGORY, coroutineTraceName + if (continuationCount < 0) "" else continuationCount, ) .addTerminatingFlow(continuationId) .emit() continuationId = nextRandomInt() } else { Trace.traceBegin(Trace.TRACE_TAG_APP, coroutineTraceName) } if (continuationCount >= 0) continuationCount++ storage.updateDataForContinuation(contextTraceData, continuationId) return oldState } Loading @@ -342,7 +382,7 @@ internal class TraceContextElement( * -------------------------------------------------------------------------------------------- * Thread #2 | [update]...x....x..^[restore] * -------------------------------------------------------------------------------------------- * Thread #3 | [ ... update ... ] ....^ [restore] * Thread #3 | [ ... update ... ] ...^ [restore] * ``` * * (`...` indicate coroutine body is running; whitespace indicates the thread is not scheduled; Loading @@ -356,34 +396,35 @@ internal class TraceContextElement( // thread after the last suspension point. This is why we use a [TraceStateHolder]: // so we can end the correct number of trace sections, restoring the thread to its state // prior to the last call to [updateThreadContext]. if (oldState !== traceThreadLocal.get()) { if (Trace.isTagEnabled(Trace.TRACE_TAG_APP)) { contextTraceData?.endAllOnThread() val storage = traceThreadLocal.get() ?: return if (storage.data === oldState) return val contId = storage.restoreDataForSuspension(oldState) if (usePerfettoSdk) { PerfettoTrace.end(PerfettoTraceConfig.COROUTINE_CATEGORY).addFlow(contId).emit() } else { Trace.traceEnd(Trace.TRACE_TAG_APP) // end: coroutineTraceName } traceThreadLocal.set(oldState) } } override fun copyForChild(): CopyableThreadContextElement<TraceData?> { debug { copyForChildTraceMessage } try { Trace.traceBegin(Trace.TRACE_TAG_APP, copyForChildTraceMessage) Trace.traceBegin(Trace.TRACE_TAG_APP, copyForChildTraceMessage) // begin: TCE#copy // Root is a special case in which the name is copied to the child by default. // Otherwise, everything launched on a coroutine would have an empty name by default return createChildContext(if (isRoot) name else null) } finally { Trace.traceEnd(Trace.TRACE_TAG_APP) // end: copyForChildTraceMessage Trace.traceEnd(Trace.TRACE_TAG_APP) // end: TCE#copy } } override fun mergeForChild(overwritingElement: CoroutineContext.Element): CoroutineContext { debug { mergeForChildTraceMessage } try { Trace.traceBegin(Trace.TRACE_TAG_APP, mergeForChildTraceMessage) Trace.traceBegin(Trace.TRACE_TAG_APP, mergeForChildTraceMessage) // begin: TCE#merge return createChildContext(overwritingElement[CoroutineTraceName]?.name) } finally { Trace.traceEnd(Trace.TRACE_TAG_APP) // end: mergeForChildTraceMessage Trace.traceEnd(Trace.TRACE_TAG_APP) // end: TCE#merge } } Loading @@ -394,7 +435,7 @@ internal class TraceContextElement( walkStackForClassName(shouldIgnoreClassName) else name ?: "", isRoot = false, countContinuations = countContinuations, countContinuations = continuationCount >= 0, walkStackForDefaultNames = walkStackForDefaultNames, shouldIgnoreClassName = shouldIgnoreClassName, parentId = currentId, Loading Loading @@ -440,6 +481,8 @@ private const val UNEXPECTED_TRACE_DATA_ERROR_MESSAGE = "Overwriting context element with non-empty trace data. There should only be one " + "TraceContextElement per coroutine, and it should be installed in the root scope. " @PublishedApi internal const val COROUTINE_EXECUTION: String = "coroutine execution;" @PublishedApi internal const val TAG: String = "CoroutineTracing" @PublishedApi internal const val DEBUG: Boolean = false Loading
tracinglib/core/src/coroutines/TraceData.kt +163 −36 Original line number Diff line number Diff line Loading @@ -14,12 +14,18 @@ * limitations under the License. */ @file:OptIn(ExperimentalContracts::class) package com.android.app.tracing.coroutines import android.os.Trace import com.android.app.tracing.beginSlice import com.android.app.tracing.endSlice import com.android.systemui.Flags import java.util.ArrayDeque import kotlin.contracts.ExperimentalContracts import kotlin.math.max import kotlinx.coroutines.CoroutineStart.UNDISPATCHED /** * Represents a section of code executing in a coroutine. This may be split up into multiple slices Loading @@ -29,23 +35,138 @@ import java.util.ArrayDeque */ private typealias TraceSection = String private class MutableInt(var value: Int) /** Use a final subclass to avoid virtual calls (b/316642146). */ @PublishedApi internal class TraceDataThreadLocal : ThreadLocal<TraceStorage?>() { override fun initialValue(): TraceStorage? { return if (Flags.coroutineTracing()) { TraceStorage(null) } else { null } } } private class ThreadLocalInt : ThreadLocal<MutableInt>() { override fun initialValue(): MutableInt { return MutableInt(0) /** * There should only be one instance of this class per thread. * * @param openSliceCount ThreadLocal counter for how many open trace sections there are on the * current thread. This is needed because it is possible that on a multi-threaded dispatcher, one * of the threads could be slow, and [TraceContextElement.restoreThreadContext] might be invoked * _after_ the coroutine has already resumed and modified [TraceData] - either adding or removing * trace sections and changing the count. If we did not store this thread-locally, then we would * incorrectly end too many or too few trace sections. */ @PublishedApi internal class TraceStorage(internal var data: TraceData?) { /** * Counter for tracking which index to use in the [continuationIds] and [openSliceCount] arrays. * `contIndex` is used to keep track of the stack used for managing tracing state when * coroutines are resumed and suspended in a nested way. * * `-1` indicates no coroutine is currently running * * `0` indicates one coroutine is running * * `>1` indicates the current coroutine is resumed inside another coroutine, e.g. due to an * unconfined dispatcher or [UNDISPATCHED] launch. */ internal var contIndex = -1 internal lateinit var continuationIds: IntArray private lateinit var debugCounterTrack: String init { if (DebugSysProps.UsePerfettoSdk) { continuationIds = IntArray(INITIAL_THREAD_LOCAL_STACK_SIZE) } if (DEBUG) { debugCounterTrack = "TCE#${Thread.currentThread().threadId()}" } } /** * Count of slices opened on the current thread due to current [TraceData] that must be closed * when it is removed. If another [data] overwrites the current one, all trace sections due to * current [data] must be closed. The overwriting [data] will handle updating itself when * [TraceContextElement.updateThreadContext] is called for it. * * Expected nesting should never exceed 255, so use a [ByteArray]. If nesting _does_ exceed 255, * it indicates there is already something very wrong with the trace, so we will not waste CPU * cycles error checking. */ internal var openSliceCount = ByteArray(INITIAL_THREAD_LOCAL_STACK_SIZE) /** * ThreadLocal counter for how many open trace sections there are. This is needed because it is * possible that on a multi-threaded dispatcher, one of the threads could be slow, and * [TraceContextElement.restoreThreadContext] might be invoked _after_ the coroutine has already * resumed and modified [TraceData] - either adding or removing trace sections and changing the * count. If we did not store this thread-locally, then we would incorrectly end too many or too few * trace sections. * Adds a new trace section to the current trace data. The slice will be traced on the current * thread immediately. This slice will not propagate to parent coroutines, or to child * coroutines that have already started. */ private val openSliceCount = ThreadLocalInt() @PublishedApi internal fun beginCoroutineTrace(name: String) { val data = data ?: return data.beginSpan(name) if (0 <= contIndex && contIndex < openSliceCount.size) { openSliceCount[contIndex]++ } } /** * Ends the trace section and validates it corresponds with an earlier call to * [beginCoroutineTrace]. The trace slice will immediately be removed from the current thread. * This information will not propagate to parent coroutines, or to child coroutines that have * already started. * * @return true if span was ended, `false` if not */ @PublishedApi internal fun endCoroutineTrace() { if (data?.endSpan() == true && 0 <= contIndex && contIndex < openSliceCount.size) { openSliceCount[contIndex]-- } } /** Update [data] for continuation */ fun updateDataForContinuation(contextTraceData: TraceData?, contId: Int) { data = contextTraceData val n = ++contIndex if (DEBUG) { Trace.traceCounter(Trace.TRACE_TAG_APP, debugCounterTrack, n) } if (n < 0 || MAX_THREAD_LOCAL_STACK_SIZE <= n) return // fail-safe var size = openSliceCount.size if (n >= size) { size = max(2 * size, MAX_THREAD_LOCAL_STACK_SIZE) openSliceCount = openSliceCount.copyInto(ByteArray(size)) if (::continuationIds.isInitialized) { continuationIds = continuationIds.copyInto(IntArray(size)) } } openSliceCount[n] = data?.beginAllOnThread() ?: 0 if (::continuationIds.isInitialized && 0 < contId) { continuationIds[n] = contId } } /** Update [data] for suspension */ fun restoreDataForSuspension(oldState: TraceData?): Int { data = oldState val n = contIndex-- if (DEBUG) { Trace.traceCounter(Trace.TRACE_TAG_APP, debugCounterTrack, n) } if (n < 0 || MAX_THREAD_LOCAL_STACK_SIZE <= n) return 0 // fail-safe if (Trace.isTagEnabled(Trace.TRACE_TAG_APP)) { val lastState = openSliceCount[n] var i = 0 while (i < lastState) { endSlice() i++ } } return if (::continuationIds.isInitialized && n < continuationIds.size) continuationIds[n] else 0 } } /** * Used for storing trace sections so that they can be added and removed from the currently running Loading @@ -62,27 +183,24 @@ internal class TraceData(internal val currentId: Int, private val strictMode: Bo internal lateinit var slices: ArrayDeque<TraceSection> /** Adds current trace slices back to the current thread. Called when coroutine is resumed. */ internal fun beginAllOnThread() { /** * Adds current trace slices back to the current thread. Called when coroutine is resumed. * * @return number of new trace sections started */ internal fun beginAllOnThread(): Byte { if (Trace.isTagEnabled(Trace.TRACE_TAG_APP)) { strictModeCheck() if (::slices.isInitialized) { slices.descendingIterator().forEach { sectionName -> beginSlice(sectionName) } openSliceCount.get()!!.value = slices.size var count: Byte = 0 slices.descendingIterator().forEach { sectionName -> beginSlice(sectionName) count++ } return count } } /** * Removes all current trace slices from the current thread. Called when coroutine is suspended. */ internal fun endAllOnThread() { if (Trace.isTagEnabled(Trace.TRACE_TAG_APP)) { strictModeCheck() val sliceCount = openSliceCount.get()!! repeat(sliceCount.value) { endSlice() } sliceCount.value = 0 } return 0 } /** Loading @@ -91,14 +209,12 @@ internal class TraceData(internal val currentId: Int, private val strictMode: Bo * coroutines, or to child coroutines that have already started. The unique ID is used to verify * that the [endSpan] is corresponds to a [beginSpan]. */ @PublishedApi internal fun beginSpan(name: String) { strictModeCheck() if (!::slices.isInitialized) { slices = ArrayDeque<TraceSection>(4) } slices.push(name) openSliceCount.get()!!.value = slices.size beginSlice(name) } Loading @@ -106,18 +222,20 @@ internal class TraceData(internal val currentId: Int, private val strictMode: Bo * Ends the trace section and validates it corresponds with an earlier call to [beginSpan]. The * trace slice will immediately be removed from the current thread. This information will not * propagate to parent coroutines, or to child coroutines that have already started. * * @return `true` if [endSlice] was called, `false` otherwise */ @PublishedApi internal fun endSpan() { internal fun endSpan(): Boolean { strictModeCheck() // Should never happen, but we should be defensive rather than crash the whole application if (::slices.isInitialized && slices.size > 0) { if (::slices.isInitialized && !slices.isEmpty()) { slices.pop() openSliceCount.get()!!.value = slices.size endSlice() return true } else if (strictMode) { throw IllegalStateException(INVALID_SPAN_END_CALL_ERROR_MESSAGE) } return false } public override fun toString(): String = Loading @@ -126,16 +244,25 @@ internal class TraceData(internal val currentId: Int, private val strictMode: Bo "{${slices.joinToString(separator = "\", \"", prefix = "\"", postfix = "\"")}}" } else { "{<uninitialized>}" } } + "@${hashCode()}" } else super.toString() private fun strictModeCheck() { if (strictMode && traceThreadLocal.get() !== this) { if (strictMode && traceThreadLocal.get()?.data !== this) { throw ConcurrentModificationException(STRICT_MODE_ERROR_MESSAGE) } } } private const val INITIAL_THREAD_LOCAL_STACK_SIZE = 4 /** * The maximum allowed stack size for coroutine re-entry. Anything above this will cause malformed * traces. It should be set to a high number that should never happen, meaning if it were to occur, * there is likely an underlying bug. */ private const val MAX_THREAD_LOCAL_STACK_SIZE = 512 private const val INVALID_SPAN_END_CALL_ERROR_MESSAGE = "TraceData#endSpan called when there were no active trace sections in its scope." Loading
tracinglib/demo/src/experiments/LaunchNested.kt +16 −15 Original line number Diff line number Diff line Loading @@ -15,32 +15,33 @@ */ package com.example.tracing.demo.experiments import com.android.app.tracing.coroutines.launchTraced as launch import com.android.app.tracing.coroutines.launchTraced import com.android.app.tracing.coroutines.traceCoroutine import com.example.tracing.demo.FixedThread1 import com.example.tracing.demo.FixedThread2 import com.example.tracing.demo.FixedThread3 import javax.inject.Inject import javax.inject.Singleton import kotlinx.coroutines.CoroutineDispatcher import kotlinx.coroutines.CoroutineScope import kotlinx.coroutines.CoroutineStart import kotlinx.coroutines.coroutineScope import kotlinx.coroutines.delay import kotlinx.coroutines.withContext @Singleton class LaunchNested @Inject constructor( @FixedThread1 private var dispatcher1: CoroutineDispatcher, @FixedThread2 private var dispatcher2: CoroutineDispatcher, @FixedThread3 private val dispatcher3: CoroutineDispatcher, ) : TracedExperiment() { class LaunchNested @Inject constructor(@FixedThread1 private var dispatcher1: CoroutineDispatcher) : TracedExperiment() { override val description: String = "launch{launch{launch{launch{}}}}" override suspend fun runExperiment(): Unit = coroutineScope { launch("launch(thread1)", dispatcher1) { forceSuspend("111", 5) launch("launch(thread2)", dispatcher2) { forceSuspend("222", 5) launch("launch(thread3)", dispatcher3) { forceSuspend("333", 5) } fun CoroutineScope.recursivelyLaunch(n: Int) { if (n == 400) return launchTraced("launch#$n", start = CoroutineStart.UNDISPATCHED) { traceCoroutine("trace-span") { recursivelyLaunch(n + 1) delay(1) } } } withContext(dispatcher1) { recursivelyLaunch(0) } } }
tracinglib/demo/src/experiments/LaunchStressTest.kt +33 −5 File changed.Preview size limit exceeded, changes collapsed. Show changes