Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 5f430310 authored by Peter Kalauskas's avatar Peter Kalauskas
Browse files

Bytecode optimizations for coroutine tracing 

 - Use ArrayDeque instead of ArrayList for trace sections

 - Use String instead of TraceSection object, which included an id.
   We verify the correctness of the trace section in our unit tests.
   Additional runtime checks are uncessary since they add overhead,
   and in the worst-case scenario, a malformed trace only affect debug
   tooling.

 - Access TraceData through the CoroutineContext instead of the global
   ThreadLocal when possible.

 - New test to verify trace storage is null after performing many
   multi-threaded operations that are traced.

Flag: ACONFIG com.android.systemui.coroutine_tracing DISABLED
Bug: 289353932
Test: atest tracinglib-host-test tracinglib-robolectric-test
Change-Id: Ib34bb265a54a23e37d7e5a1369aa329656b47633
parent f92e52f2

tracinglib/Android.bp

+1 −0
Original line number Diff line number Diff line
@@ -37,6 +37,7 @@ java_library { 
    srcs: ["src/androidMinApi19/kotlin/**/*.kt"],

    sdk_version: "31",

    min_sdk_version: "19",

    java_version: "17",

}



java_test_host {

tracinglib/src/androidMinApi19/kotlin/com/android/app/tracing/TraceProxy.jetpack.kt

+2 −2
Original line number Diff line number Diff line
@@ -17,7 +17,7 @@ 
package com.android.app.tracing



import androidx.tracing.Trace

import kotlin.random.Random

import java.util.concurrent.ThreadLocalRandom



@PublishedApi

internal actual fun isEnabled(): Boolean {
@@ -69,7 +69,7 @@ internal actual fun instant(eventName: String) { 


internal actual fun instantForTrack(trackName: String, eventName: String) {

    if (Trace.isEnabled()) {

        val cookie = Random.nextInt()

        val cookie = ThreadLocalRandom.current().nextInt()

        val name = "instant:${namedSlice(trackName,eventName)}"

        asyncTraceBegin(name, cookie)

        asyncTraceEnd(name, cookie)

tracinglib/src/commonMain/kotlin/com/android/app/tracing/TraceUtils.kt

+2 −2
Original line number Diff line number Diff line
@@ -17,7 +17,7 @@ 
package com.android.app.tracing



import com.android.app.tracing.coroutines.traceCoroutine

import kotlin.random.Random

import java.util.concurrent.ThreadLocalRandom



/**

 * Writes a trace message to indicate that a given section of code has begun running __on the
@@ -155,7 +155,7 @@ object TraceUtils { 
     */

    @JvmStatic

    inline fun <T> traceAsync(trackName: String, method: String, block: () -> T): T {

        val cookie = Random.nextInt()

        val cookie = ThreadLocalRandom.current().nextInt()

        asyncTraceForTrackBegin(trackName, method, cookie)

        try {

            return block()

tracinglib/src/commonMain/kotlin/com/android/app/tracing/coroutines/CoroutineTracing.kt

+26 −48
Original line number Diff line number Diff line
@@ -16,26 +16,27 @@ 


package com.android.app.tracing.coroutines



import android.util.Log

import com.android.app.tracing.asyncTraceForTrackBegin

import com.android.app.tracing.asyncTraceForTrackEnd

import com.android.app.tracing.isEnabled

import com.android.systemui.Flags.coroutineTracing

import java.util.concurrent.ThreadLocalRandom

import kotlin.contracts.ExperimentalContracts

import kotlin.contracts.InvocationKind

import kotlin.contracts.contract

import kotlin.coroutines.CoroutineContext

import kotlin.coroutines.EmptyCoroutineContext

import kotlin.coroutines.coroutineContext

import kotlin.random.Random

import kotlinx.coroutines.CoroutineScope

import kotlinx.coroutines.Deferred

import kotlinx.coroutines.Job

import kotlinx.coroutines.async

import kotlinx.coroutines.currentCoroutineContext

import kotlinx.coroutines.launch

import kotlinx.coroutines.runBlocking

import kotlinx.coroutines.withContext



@PublishedApi internal const val DEBUG_COROUTINE_TRACING = false

@PublishedApi internal const val TAG = "CoroutineTracing"

@PublishedApi internal const val DEFAULT_TRACK_NAME = "AsyncTraces"



@PublishedApi internal const val DEFAULT_TRACK_NAME = "Coroutines"



/**

 * Convenience function for calling [CoroutineScope.launch] with [traceCoroutine] to enable tracing.
@@ -166,59 +167,36 @@ suspend inline fun <T> withContext( 
 * @see endSlice

 * @see traceCoroutine

 */

@OptIn(ExperimentalContracts::class)

suspend inline fun <T> traceCoroutine(spanName: () -> String, block: () -> T): T {

    contract {

        callsInPlace(spanName, InvocationKind.AT_MOST_ONCE)

        callsInPlace(block, InvocationKind.EXACTLY_ONCE)

    }



    // For coroutine tracing to work, trace spans must be added and removed even when

    // 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.

    val tracer = getTraceData()

    var spanString = "<none>"

    var coroutineSpanCookie = TraceData.INVALID_SPAN

    when (tracer) {

        is MissingTraceData -> logVerbose(tracer.message, spanName)

        is TraceData -> {

            spanString = spanName()

            coroutineSpanCookie = tracer.beginSpan(spanString)

        }

    }

    val tracer = currentCoroutineContext()[TraceContextElement]?.traceData



    // For now, also trace to "AsyncTraces". This will allow us to verify the correctness

    // of the COROUTINE_TRACING feature flag.

    val asyncTraceCookie =

        if (isEnabled()) Random.nextInt(TraceData.FIRST_VALID_SPAN, Int.MAX_VALUE)

        else TraceData.INVALID_SPAN

    if (asyncTraceCookie != TraceData.INVALID_SPAN) {

        asyncTraceForTrackBegin(DEFAULT_TRACK_NAME, spanString, asyncTraceCookie)

    }

    val asyncTracingEnabled = isEnabled()

    val spanString = if (tracer != null || asyncTracingEnabled) spanName() else "<none>"



    tracer?.beginSpan(spanString)



    // Also trace to the "Coroutines" async track. This makes it easy to see the duration of

    // coroutine spans. When the coroutine_tracing flag is enabled, those same names will

    // appear in small slices on each thread as the coroutines are suspended and resumed.

    val cookie = if (asyncTracingEnabled) ThreadLocalRandom.current().nextInt() else 0

    if (asyncTracingEnabled) asyncTraceForTrackBegin(DEFAULT_TRACK_NAME, spanString, cookie)

    try {

        return block()

    } finally {

        if (asyncTraceCookie != TraceData.INVALID_SPAN) {

            asyncTraceForTrackEnd(DEFAULT_TRACK_NAME, spanString, asyncTraceCookie)

        }

        if (tracer is TraceData) {

            tracer.endSpan(coroutineSpanCookie)

        }

        if (asyncTracingEnabled) asyncTraceForTrackEnd(DEFAULT_TRACK_NAME, spanString, cookie)

        tracer?.endSpan()

    }

}



/** @see traceCoroutine */

suspend inline fun <T> traceCoroutine(spanName: String, block: () -> T): T =

    traceCoroutine({ spanName }, block)
 


@PublishedApi

internal suspend fun getTraceData(): TraceStatus {

    return if (!coroutineTracing()) {

        MissingTraceData("Experimental flag COROUTINE_TRACING is off")

    } else if (coroutineContext[TraceContextElement] == null) {

        MissingTraceData("Current CoroutineContext is missing TraceContextElement")

    } else {

        threadLocalTrace.get() ?: MissingTraceData("ThreadLocal TraceData is null")

    }

}



@PublishedApi

internal inline fun logVerbose(logMessage: String, spanName: () -> String) {

    if (DEBUG_COROUTINE_TRACING && Log.isLoggable(TAG, Log.VERBOSE)) {

        Log.v(TAG, "$logMessage. Dropping trace section: \"${spanName()}\"")

    }

}

tracinglib/src/commonMain/kotlin/com/android/app/tracing/coroutines/TraceContextElement.kt

+23 −7
Original line number Diff line number Diff line
@@ -25,6 +25,19 @@ import kotlinx.coroutines.CopyableThreadContextElement 
import kotlinx.coroutines.CoroutineDispatcher

import kotlinx.coroutines.CoroutineName



/**

 * Thread-local storage for giving each thread a unique [TraceData]. It can only be used when paired

 * with a [TraceContextElement].

 *

 * [CURRENT_TRACE] will be `null` if either 1) we aren't in a coroutine, or 2) the current coroutine

 * context does not have [TraceContextElement]. In both cases, writing to this thread-local would be

 * undefined behavior if it were not null, which is why we use null as the default value rather than

 * an empty TraceData.

 *

 * @see traceCoroutine

 */

internal val CURRENT_TRACE = ThreadLocal<TraceData?>()



/**

 * If `true`, the CoroutineDispatcher and CoroutineName will be included in the trace each time the

 * coroutine context changes. This makes the trace extremely noisy, so it is off by default.
@@ -52,18 +65,21 @@ private fun CoroutineContext.nameForTrace(): String { 
 *

 * @see traceCoroutine

 */

internal class TraceContextElement(private val traceData: TraceData = TraceData()) :

@PublishedApi

internal class TraceContextElement(@PublishedApi internal val traceData: TraceData = TraceData()) :

    CopyableThreadContextElement<TraceData?> {



    internal companion object Key : CoroutineContext.Key<TraceContextElement>

    @PublishedApi internal companion object Key : CoroutineContext.Key<TraceContextElement>



    override val key: CoroutineContext.Key<*>

        get() = Key



    override fun updateThreadContext(context: CoroutineContext): TraceData? {

        val oldState = threadLocalTrace.get()

        val oldState = CURRENT_TRACE.get()

        // oldState should never be null because we always initialize the thread-local with a

        // non-null instance,

        oldState?.endAllOnThread()

        threadLocalTrace.set(traceData)

        CURRENT_TRACE.set(traceData)

        if (DEBUG_COROUTINE_CONTEXT_UPDATES) beginSlice(context.nameForTrace())

        traceData.beginAllOnThread()

        return oldState
@@ -72,15 +88,15 @@ internal class TraceContextElement(private val traceData: TraceData = TraceData( 
    override fun restoreThreadContext(context: CoroutineContext, oldState: TraceData?) {

        if (DEBUG_COROUTINE_CONTEXT_UPDATES) endSlice()

        traceData.endAllOnThread()

        threadLocalTrace.set(oldState)

        CURRENT_TRACE.set(oldState)

        oldState?.beginAllOnThread()

    }



    override fun copyForChild(): CopyableThreadContextElement<TraceData?> {

        return TraceContextElement(traceData.copy())

        return TraceContextElement(traceData.clone())

    }



    override fun mergeForChild(overwritingElement: CoroutineContext.Element): CoroutineContext {

        return TraceContextElement(traceData.copy())

        return TraceContextElement(traceData.clone())

    }

}