tracinglib: improve continuation performance (f3e6de2c) · Commits · e / os / android_frameworks_libs_systemui

tracinglib/core/src/coroutines/TraceContextElement.kt

+82 −81

Original line number	Diff line number	Diff line
		@@ -51,13 +51,11 @@ import kotlinx.coroutines.ExperimentalCoroutinesApi
		*/
		@PublishedApi internal val traceThreadLocal: TraceDataThreadLocal = TraceDataThreadLocal()

		private val alwaysEnableStackWalker: Boolean by lazy {
		private val alwaysEnableStackWalker =
		SystemProperties.getBoolean("debug.coroutine_tracing.walk_stack_override", false)
		}

		private val alwaysEnableContinuationCounting: Boolean by lazy {
		private val alwaysEnableContinuationCounting =
		SystemProperties.getBoolean("debug.coroutine_tracing.count_continuations_override", false)
		}

		/**
		* Returns a new [TraceContextElement] (or [EmptyCoroutineContext] if `coroutine_tracing` feature is
		@@ -96,40 +94,39 @@ private val alwaysEnableContinuationCounting: Boolean by lazy {
		* @param walkStackForDefaultNames whether to walk the stack and use the class name of the current
		* suspending function if child does not have a name that was manually specified. Walking the
		* stack is very expensive so this should not be used in production.
		* @param countContinuations whether to include an extra trace section showing the total number of
		* times a coroutine has suspended and resumed.
		* @param countContinuations whether to include extra info in the trace section indicating the total
		* number of times a coroutine has suspended and resumed (e.g. ";n=#")
		* @param countDepth whether to include extra info in the trace section indicating the how far from
		* the root trace context this coroutine is (e.g. ";d=#")
		* @param testMode changes behavior is several ways: 1) parent names and sibling counts are
		* concatenated with the name of the child. This can result in extremely long trace names, which
		* is why it is only for testing. 2) additional strict-mode checks are added to coroutine tracing
		* machinery. These checks are expensive and should only be used for testing. 3) omits "coroutine
		* execution" trace slices, and omits coroutine metadata slices
		* execution" trace slices, and omits coroutine metadata slices. If [testMode] is enabled,
		* [countContinuations] and [countDepth] are ignored.
		* @param shouldIgnoreClassName lambda that takes binary class name (as returned from
		* [StackFrame.getClassName] and returns true if it should be ignored (e.g. search for relevant
		* class name should continue) or false otherwise.
		*/
		public fun createCoroutineTracingContext(
		name: String = "UnnamedScope",
		walkStackForDefaultNames: Boolean = false,
		countContinuations: Boolean = false,
		countDepth: Boolean = false,
		testMode: Boolean = false,
		walkStackForDefaultNames: Boolean = false,
		shouldIgnoreClassName: (String) -> Boolean = { false },
		): CoroutineContext {
		return if (Flags.coroutineTracing()) {
		TraceContextElement(
		name = name,
		// Minor perf optimization: no need to create TraceData() for root scopes since all
		// launches require creation of child via [copyForChild] or [mergeForChild].
		contextTraceData = null,
		config =
		TraceConfig(
		isRoot = true,
		countContinuations =
		!testMode && (countContinuations \|\| alwaysEnableContinuationCounting),
		walkStackForDefaultNames = walkStackForDefaultNames \|\| alwaysEnableStackWalker,
		testMode = testMode,
		shouldIgnoreClassName = shouldIgnoreClassName,
		countContinuations = countContinuations \|\| alwaysEnableContinuationCounting,
		),
		parentId = null,
		inheritedTracePrefix = "",
		coroutineDepth = 0,
		inheritedTracePrefix = if (testMode) "" else null,
		coroutineDepth = if (!testMode && countDepth) 0 else -1,
		)
		} else {
		EmptyCoroutineContext
		@@ -194,24 +191,11 @@ internal open class CoroutineTraceName(internal val name: String) : CoroutineCon
		level = DeprecationLevel.ERROR,
		)
		public operator fun plus(other: CoroutineTraceName): CoroutineTraceName {
		debug { "#plus(${other.currentId})" }
		debug { "CTN#plus;c=$currentId other=${other.currentId}" }
		return other
		}

		@OptIn(ExperimentalContracts::class)
		protected inline fun debug(message: () -> String) {
		contract { callsInPlace(message, InvocationKind.AT_MOST_ONCE) }
		if (DEBUG) Log.d(TAG, "${this::class.java.simpleName}@$currentId${message()}")
		}
		}

		internal class TraceConfig(
		val walkStackForDefaultNames: Boolean,
		val testMode: Boolean,
		val shouldIgnoreClassName: (String) -> Boolean,
		val countContinuations: Boolean,
		)

		/**
		* Used for tracking parent-child relationship of coroutines and persisting [TraceData] when
		* coroutines are suspended and resumed.
		@@ -230,6 +214,7 @@ internal class TraceConfig(
		* would be used instead: `root-scope:3^`
		* @param coroutineDepth How deep the coroutine is relative to the top-level [CoroutineScope]
		* containing the original [TraceContextElement] from which this [TraceContextElement] was copied.
		* If -1, counting depth is disabled
		* @see createCoroutineTracingContext
		* @see nameCoroutine
		* @see traceCoroutine
		@@ -237,31 +222,43 @@ internal class TraceConfig(
		@OptIn(DelicateCoroutinesApi::class, ExperimentalCoroutinesApi::class)
		internal class TraceContextElement(
		name: String,
		internal val contextTraceData: TraceData?,
		private val config: TraceConfig,
		private val isRoot: Boolean,
		private val countContinuations: Boolean,
		private val walkStackForDefaultNames: Boolean,
		private val shouldIgnoreClassName: (String) -> Boolean,
		parentId: Int?,
		inheritedTracePrefix: String,
		inheritedTracePrefix: String?,
		coroutineDepth: Int,
		) : CopyableThreadContextElement<TraceData?>, CoroutineTraceName(name) {

		private val coroutineTraceName =
		if (config.testMode) "$inheritedTracePrefix$name"
		else "$name;d=$coroutineDepth;c=$currentId;p=${parentId ?: "none"}"

		init {
		debug { "#init: name=$name" }
		Trace.traceBegin(Trace.TRACE_TAG_APP, "TraceContextElement#init[$coroutineTraceName]")
		val traceSection = "TCE#init name=$name"
		debug { traceSection }
		Trace.traceBegin(Trace.TRACE_TAG_APP, traceSection)
		}

		// Minor perf optimization: no need to create TraceData() for root scopes since all launches
		// require creation of child via [copyForChild] or [mergeForChild].
		internal val contextTraceData: TraceData? =
		if (isRoot) null else TraceData(currentId, strictMode = inheritedTracePrefix != null)

		private val coroutineTraceName =
		if (inheritedTracePrefix == null) {
		"coroutine execution;$name;c=$currentId;p=${parentId ?: "none"}${if (coroutineDepth == -1) "" else ";d=$coroutineDepth"}"
		} else {
		"$inheritedTracePrefix$name"
		}

		private var continuationCount = 0
		private val childDepth = coroutineDepth + 1
		private var childCoroutineCount = if (config.testMode) AtomicInteger(0) else null
		private val childDepth =
		if (inheritedTracePrefix != null \|\| coroutineDepth == -1) -1 else coroutineDepth + 1
		private val childCoroutineCount = if (inheritedTracePrefix != null) AtomicInteger(0) else null

		private val copyForChildTraceMessage = "TraceContextElement#copyForChild[$coroutineTraceName]"
		private val mergeForChildTraceMessage = "TraceContextElement#mergeForChild[$coroutineTraceName]"
		private val copyForChildTraceMessage = "TCE#copy;c=$currentId]"
		private val mergeForChildTraceMessage = "TCE#merge;c=$currentId]"

		init {
		Trace.traceEnd(Trace.TRACE_TAG_APP)
		Trace.traceEnd(Trace.TRACE_TAG_APP) // end: "TCE#init"
		}

		/**
		@@ -282,16 +279,14 @@ internal class TraceContextElement(
		@SuppressLint("UnclosedTrace")
		public override fun updateThreadContext(context: CoroutineContext): TraceData? {
		val oldState = traceThreadLocal.get()
		debug { "#updateThreadContext oldState=$oldState" }
		debug { "TCE#update;c=$currentId oldState=${oldState?.currentId}" }
		if (oldState !== contextTraceData) {
		if (!config.testMode) {
		Trace.traceBegin(Trace.TRACE_TAG_APP, "coroutine execution")
		}
		Trace.traceBegin(Trace.TRACE_TAG_APP, coroutineTraceName)
		if (config.countContinuations) {
		Trace.traceBegin(Trace.TRACE_TAG_APP, "continuation: #${continuationCount++}")
		}
		traceThreadLocal.set(contextTraceData)
		Trace.traceBegin(
		Trace.TRACE_TAG_APP,
		if (countContinuations) "$coroutineTraceName;n=${continuationCount++}"
		else coroutineTraceName,
		)
		// 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
		@@ -329,7 +324,7 @@ internal class TraceContextElement(
		* ```
		*/
		public override fun restoreThreadContext(context: CoroutineContext, oldState: TraceData?) {
		debug { "#restoreThreadContext restoring=$oldState" }
		debug { "TCE#restore;c=$currentId restoring=${oldState?.currentId}" }
		// We not use the `TraceData` object here because it may have been modified on another
		// 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
		@@ -337,21 +332,15 @@ internal class TraceContextElement(
		if (oldState !== traceThreadLocal.get()) {
		contextTraceData?.endAllOnThread()
		traceThreadLocal.set(oldState)
		if (!config.testMode) {
		Trace.traceEnd(Trace.TRACE_TAG_APP) // end: "coroutine execution"
		}
		Trace.traceEnd(Trace.TRACE_TAG_APP) // end: contextMetadata
		if (config.countContinuations) {
		Trace.traceEnd(Trace.TRACE_TAG_APP) // end: continuation: #
		}
		Trace.traceEnd(Trace.TRACE_TAG_APP) // end: coroutineTraceName
		}
		}

		public override fun copyForChild(): CopyableThreadContextElement<TraceData?> {
		debug { "#copyForChild" }
		debug { copyForChildTraceMessage }
		try {
		Trace.traceBegin(Trace.TRACE_TAG_APP, copyForChildTraceMessage)
		return createChildContext()
		return createChildContext(null)
		} finally {
		Trace.traceEnd(Trace.TRACE_TAG_APP) // end: copyForChildTraceMessage
		}
		@@ -360,8 +349,7 @@ internal class TraceContextElement(
		public override fun mergeForChild(
		overwritingElement: CoroutineContext.Element
		): CoroutineContext {
		debug { "#mergeForChild" }
		if (DEBUG) {
		debug {
		(overwritingElement as? TraceContextElement)?.let {
		Log.e(
		TAG,
		@@ -370,6 +358,7 @@ internal class TraceContextElement(
		UNEXPECTED_TRACE_DATA_ERROR_MESSAGE,
		)
		}
		return@debug mergeForChildTraceMessage
		}
		try {
		Trace.traceBegin(Trace.TRACE_TAG_APP, mergeForChildTraceMessage)
		@@ -380,23 +369,25 @@ internal class TraceContextElement(
		}
		}

		private fun createChildContext(name: String? = null): TraceContextElement {
		val childName =
		name
		?: if (config.walkStackForDefaultNames)
		walkStackForClassName(config.shouldIgnoreClassName)
		else ""
		debug { "#createChildContext: \"${this.name}\" has new child with name \"${childName}\"" }
		private fun createChildContext(childName: String?): TraceContextElement {
		return TraceContextElement(
		name = childName,
		contextTraceData = TraceData(strictMode = config.testMode),
		config = config,
		name =
		childName
		?: if (walkStackForDefaultNames) {
		walkStackForClassName(shouldIgnoreClassName)
		} else {
		""
		},
		isRoot = false,
		countContinuations = countContinuations,
		walkStackForDefaultNames = walkStackForDefaultNames,
		shouldIgnoreClassName = shouldIgnoreClassName,
		parentId = currentId,
		inheritedTracePrefix =
		if (config.testMode) {
		val childCount = childCoroutineCount?.incrementAndGet() ?: 0
		if (childCoroutineCount != null) {
		val childCount = childCoroutineCount.incrementAndGet()
		"$coroutineTraceName:$childCount^"
		} else "",
		} else null,
		coroutineDepth = childDepth,
		)
		}
		@@ -439,3 +430,13 @@ private const val UNEXPECTED_TRACE_DATA_ERROR_MESSAGE =
		@PublishedApi internal const val TAG: String = "CoroutineTracing"

		@PublishedApi internal const val DEBUG: Boolean = false

		@OptIn(ExperimentalContracts::class)
		private inline fun debug(message: () -> String) {
		contract { callsInPlace(message, InvocationKind.AT_MOST_ONCE) }
		if (DEBUG) {
		val msg = message()
		Trace.instant(Trace.TRACE_TAG_APP, msg)
		Log.d(TAG, msg)
		}
		}

tracinglib/core/src/coroutines/TraceData.kt

+2 −1

Original line number	Diff line number	Diff line
		@@ -38,13 +38,14 @@ private class TraceCountThreadLocal : ThreadLocal<Int>() {
		* Used for storing trace sections so that they can be added and removed from the currently running
		* thread when the coroutine is suspended and resumed.
		*
		* @property currentId ID of associated TraceContextElement
		* @property strictMode Whether to add additional checks to the coroutine machinery, throwing a
		* `ConcurrentModificationException` if TraceData is modified from the wrong thread. This should
		* only be set for testing.
		* @see traceCoroutine
		*/
		@PublishedApi
		internal class TraceData(private val strictMode: Boolean) {
		internal class TraceData(internal val currentId: Int, private val strictMode: Boolean) {

		internal var slices: ArrayDeque<TraceSection>? = null