diff options
Diffstat (limited to 'tracinglib/src/com')
7 files changed, 810 insertions, 0 deletions
diff --git a/tracinglib/src/com/android/app/tracing/FlowTracing.kt b/tracinglib/src/com/android/app/tracing/FlowTracing.kt new file mode 100644 index 0000000..d6fe63e --- /dev/null +++ b/tracinglib/src/com/android/app/tracing/FlowTracing.kt @@ -0,0 +1,33 @@ +/* + * Copyright (C) 2023 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package com.android.app.tracing + +import kotlinx.coroutines.flow.Flow +import kotlinx.coroutines.flow.onEach + +/** Utilities to trace Flows */ +object FlowTracing { + + /** Logs each flow element to a trace. */ + inline fun <T> Flow<T>.traceEach( + flowName: String, + logcat: Boolean = false, + crossinline valueToString: (T) -> String = { it.toString() } + ): Flow<T> { + val stateLogger = TraceStateLogger(flowName, logcat = logcat) + return onEach { stateLogger.log(valueToString(it)) } + } +} diff --git a/tracinglib/src/com/android/app/tracing/ListenersTracing.kt b/tracinglib/src/com/android/app/tracing/ListenersTracing.kt new file mode 100644 index 0000000..d73ca07 --- /dev/null +++ b/tracinglib/src/com/android/app/tracing/ListenersTracing.kt @@ -0,0 +1,39 @@ +/* + * Copyright (C) 2023 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.android.app.tracing + +/** Utilities to trace automatically computations happening for each element of a list. */ +object ListenersTracing { + + /** + * Like [forEach], but outputs a trace for each element. + * + * The ideal usage of this is to debug what's taking long in a list of Listeners. For example: + * ``` + * listeners.forEach { it.dispatch(state) } + * ``` + * + * often it's tricky to udnerstand which listener is causing delays. This can be used instead to + * log how much each listener is taking: + * ``` + * listeners.forEachTraced(TAG) { it.dispatch(state) } + * ``` + */ + inline fun <T : Any> List<T>.forEachTraced(tag: String = "", f: (T) -> Unit) { + forEach { traceSection({ "$tag#${it::javaClass.get().name}" }) { f(it) } } + } +} diff --git a/tracinglib/src/com/android/app/tracing/TraceContextElement.kt b/tracinglib/src/com/android/app/tracing/TraceContextElement.kt new file mode 100644 index 0000000..2c952e1 --- /dev/null +++ b/tracinglib/src/com/android/app/tracing/TraceContextElement.kt @@ -0,0 +1,69 @@ +/* + * Copyright (C) 2023 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.android.app.tracing + +import com.android.app.tracing.TraceUtils.Companion.instant +import com.android.app.tracing.TraceUtils.Companion.traceCoroutine +import kotlin.coroutines.CoroutineContext +import kotlinx.coroutines.CopyableThreadContextElement +import kotlinx.coroutines.CoroutineDispatcher +import kotlinx.coroutines.DelicateCoroutinesApi +import kotlinx.coroutines.ExperimentalCoroutinesApi + +/** + * Used for safely persisting [TraceData] state when coroutines are suspended and resumed. + * + * This is internal machinery for [traceCoroutine]. It cannot be made `internal` or `private` + * because [traceCoroutine] is a Public-API inline function. + * + * @see traceCoroutine + */ +@OptIn(DelicateCoroutinesApi::class) +@ExperimentalCoroutinesApi +class TraceContextElement(private val traceData: TraceData = TraceData()) : + CopyableThreadContextElement<TraceData?> { + + companion object Key : CoroutineContext.Key<TraceContextElement> + + override val key: CoroutineContext.Key<TraceContextElement> = Key + + @OptIn(ExperimentalStdlibApi::class) + override fun updateThreadContext(context: CoroutineContext): TraceData? { + val oldState = threadLocalTrace.get() + oldState?.endAllOnThread() + threadLocalTrace.set(traceData) + instant("resuming ${context[CoroutineDispatcher]}") + traceData.beginAllOnThread() + return oldState + } + + @OptIn(ExperimentalStdlibApi::class) + override fun restoreThreadContext(context: CoroutineContext, oldState: TraceData?) { + instant("suspending ${context[CoroutineDispatcher]}") + traceData.endAllOnThread() + threadLocalTrace.set(oldState) + oldState?.beginAllOnThread() + } + + override fun copyForChild(): CopyableThreadContextElement<TraceData?> { + return TraceContextElement(traceData.copy()) + } + + override fun mergeForChild(overwritingElement: CoroutineContext.Element): CoroutineContext { + return TraceContextElement(traceData.copy()) + } +} diff --git a/tracinglib/src/com/android/app/tracing/TraceData.kt b/tracinglib/src/com/android/app/tracing/TraceData.kt new file mode 100644 index 0000000..f014eab --- /dev/null +++ b/tracinglib/src/com/android/app/tracing/TraceData.kt @@ -0,0 +1,122 @@ +/* + * Copyright (C) 2023 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.android.app.tracing + +import android.os.Build +import android.util.Log +import com.android.app.tracing.TraceUtils.Companion.beginSlice +import com.android.app.tracing.TraceUtils.Companion.endSlice +import com.android.app.tracing.TraceUtils.Companion.traceCoroutine +import kotlin.random.Random + +/** + * Used for giving each thread a unique [TraceData] for thread-local storage. `null` by default. + * [threadLocalTrace] can only be used when it is paired with a [TraceContextElement]. + * + * This ThreadLocal will be `null` if either 1) we aren't in a coroutine, or 2) the coroutine we are + * in does not have a [TraceContextElement]. + * + * This is internal machinery for [traceCoroutine]. It cannot be made `internal` or `private` + * because [traceCoroutine] is a Public-API inline function. + * + * @see traceCoroutine + */ +val threadLocalTrace = ThreadLocal<TraceData?>() + +/** + * 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. + * + * This is internal machinery for [traceCoroutine]. It cannot be made `internal` or `private` + * because [traceCoroutine] is a Public-API inline function. + * + * @see traceCoroutine + */ +class TraceData { + private var slices = mutableListOf<TraceSection>() + + /** Adds current trace slices back to the current thread. Called when coroutine is resumed. */ + fun beginAllOnThread() { + slices.forEach { beginSlice(it.name) } + } + + /** + * Removes all current trace slices from the current thread. Called when coroutine is suspended. + */ + fun endAllOnThread() { + for (i in 0..slices.size) { + endSlice() + } + } + + /** + * Creates a new trace section with a unique ID and adds it to the current trace data. The slice + * will also be added to the current thread immediately. This slice will not propagate to parent + * coroutines, or to child coroutines that have already started. The unique ID is used to verify + * that the [endSpan] is corresponds to a [beginSpan]. + */ + fun beginSpan(name: String): Int { + val newSlice = TraceSection(name, Random.nextInt(FIRST_VALID_SPAN, Int.MAX_VALUE)) + slices.add(newSlice) + beginSlice(name) + return newSlice.id + } + + /** + * Used by [TraceContextElement] when launching a child coroutine so that the child coroutine's + * state is isolated from the parent. + */ + fun copy(): TraceData { + return TraceData().also { it.slices.addAll(slices) } + } + + /** + * 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. + */ + fun endSpan(id: Int) { + val v = slices.removeLast() + if (v.id != id) { + if (STRICT_MODE) { + throw IllegalArgumentException(errorMsg) + } else if (Log.isLoggable(TAG, Log.VERBOSE)) { + Log.v(TAG, errorMsg) + } + } + endSlice() + } + + companion object { + private const val TAG = "TraceData" + const val INVALID_SPAN = -1 + const val FIRST_VALID_SPAN = 1 + + /** + * If true, throw an exception instead of printing a warning when trace sections beginnings + * and ends are mismatched. + */ + private val STRICT_MODE = Build.IS_ENG + + private const val errorMsg = + "Mismatched trace section. This likely means you are accessing the trace local " + + "storage (threadLocalTrace) without a corresponding CopyableThreadContextElement." + + " This could happen if you are using a global dispatcher like Dispatchers.IO." + + " To fix this, use one of the coroutine contexts provided by the dagger scope " + + "(e.g. \"@Main CoroutineContext\")." + } +} diff --git a/tracinglib/src/com/android/app/tracing/TraceSection.kt b/tracinglib/src/com/android/app/tracing/TraceSection.kt new file mode 100644 index 0000000..c96c0e5 --- /dev/null +++ b/tracinglib/src/com/android/app/tracing/TraceSection.kt @@ -0,0 +1,35 @@ +/* + * Copyright (C) 2023 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.android.app.tracing + +import com.android.app.tracing.TraceUtils.Companion.traceCoroutine + +/** + * Represents a section of code executing in a coroutine. This can be split up into multiple slices + * on different threads as the coroutine is suspended and resumed. + * + * This is internal machinery for [traceCoroutine]. It cannot be made `internal` or `private` + * because [traceCoroutine] is a Public-API inline function. + * + * @param name the name of the slice to appear on the current thread's track. + * @param id used for matching the beginning and end of trace sections and validating correctness + * @see traceCoroutine + */ +data class TraceSection( + val name: String, + val id: Int, +) diff --git a/tracinglib/src/com/android/app/tracing/TraceStateLogger.kt b/tracinglib/src/com/android/app/tracing/TraceStateLogger.kt new file mode 100644 index 0000000..02c8737 --- /dev/null +++ b/tracinglib/src/com/android/app/tracing/TraceStateLogger.kt @@ -0,0 +1,60 @@ +/* + * Copyright (C) 2023 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.android.app.tracing + +import android.os.Trace +import android.util.Log + +/** + * Utility class used to log state changes easily in a track with a custom name. + * + * Example of usage: + * ```kotlin + * class MyClass { + * val screenStateLogger = TraceStateLogger("Screen state") + * + * fun onTurnedOn() { screenStateLogger.log("on") } + * fun onTurnedOff() { screenStateLogger.log("off") } + * } + * ``` + * + * This creates a new slice in a perfetto trace only if the state is different than the previous + * one. + */ +class TraceStateLogger( + private val trackName: String, + private val logOnlyIfDifferent: Boolean = true, + private val instantEvent: Boolean = true, + private val logcat: Boolean = false, +) { + + private var previousValue: String? = null + + /** If needed, logs the value to a track with name [trackName]. */ + fun log(newValue: String) { + if (instantEvent) { + Trace.instantForTrack(Trace.TRACE_TAG_APP, trackName, newValue) + } + if (logOnlyIfDifferent && previousValue == newValue) return + Trace.asyncTraceForTrackEnd(Trace.TRACE_TAG_APP, trackName, 0) + Trace.asyncTraceForTrackBegin(Trace.TRACE_TAG_APP, trackName, newValue, 0) + if (logcat) { + Log.d(trackName, "newValue: $newValue") + } + previousValue = newValue + } +} diff --git a/tracinglib/src/com/android/app/tracing/TraceUtils.kt b/tracinglib/src/com/android/app/tracing/TraceUtils.kt new file mode 100644 index 0000000..ec75bd2 --- /dev/null +++ b/tracinglib/src/com/android/app/tracing/TraceUtils.kt @@ -0,0 +1,452 @@ +/* + * Copyright (C) 2023 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.android.app.tracing + +import android.os.Trace +import android.os.TraceNameSupplier +import android.util.Log +import com.android.app.tracing.TraceData.Companion.FIRST_VALID_SPAN +import com.android.app.tracing.TraceData.Companion.INVALID_SPAN +import java.util.concurrent.atomic.AtomicInteger +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.ExperimentalCoroutinesApi +import kotlinx.coroutines.Job +import kotlinx.coroutines.async +import kotlinx.coroutines.launch +import kotlinx.coroutines.runBlocking +import kotlinx.coroutines.withContext + +/** + * Run a block within a [Trace] section. Calls [Trace.beginSection] before and [Trace.endSection] + * after the passed block. + */ +inline fun <T> traceSection(tag: String, block: () -> T): T { + val tracingEnabled = Trace.isTagEnabled(Trace.TRACE_TAG_APP) + if (tracingEnabled) Trace.traceBegin(Trace.TRACE_TAG_APP, tag) + return try { + // Note that as this is inline, the block section would be duplicated if it is called + // several times. For this reason, we're using the try/finally even if tracing is disabled. + block() + } finally { + if (tracingEnabled) Trace.traceEnd(Trace.TRACE_TAG_APP) + } +} + +/** + * Same as [traceSection], but the tag is provided as a lambda to help avoiding creating expensive + * strings when not needed. + */ +inline fun <T> traceSection(tag: () -> String, block: () -> T): T { + val tracingEnabled = Trace.isTagEnabled(Trace.TRACE_TAG_APP) + if (tracingEnabled) Trace.traceBegin(Trace.TRACE_TAG_APP, tag()) + return try { + block() + } finally { + if (tracingEnabled) Trace.traceEnd(Trace.TRACE_TAG_APP) + } +} + +class TraceUtils { + companion object { + const val TAG = "TraceUtils" + private const val DEBUG_COROUTINE_TRACING = false + const val DEFAULT_TRACK_NAME = "AsyncTraces" + + @JvmStatic + inline fun <T> trace(crossinline tag: () -> String, crossinline block: () -> T): T { + return traceSection(tag) { block() } + } + + @JvmStatic + inline fun <T> trace(tag: String, crossinline block: () -> T): T { + return traceSection(tag) { block() } + } + + @JvmStatic + inline fun traceRunnable(tag: String, crossinline block: () -> Unit): Runnable { + return Runnable { traceSection(tag) { block() } } + } + + @JvmStatic + inline fun traceRunnable(crossinline tag: () -> String, crossinline block: () -> Unit): Runnable { + return Runnable { traceSection(tag) { block() } } + } + + /** + * Helper function for creating a Runnable object that implements TraceNameSupplier. + * + * This is useful for posting Runnables to Handlers with meaningful names. + */ + @JvmStatic + inline fun namedRunnable(tag: String, crossinline block: () -> Unit): Runnable { + return object : Runnable, TraceNameSupplier { + override fun getTraceName(): String = tag + + override fun run() = block() + } + } + + /** + * Cookie used for async traces. Shouldn't be public, but to use it inside inline methods + * there is no other way around. + */ + val lastCookie = AtomicInteger(0) + + /** + * Creates an async slice in a track called "AsyncTraces". + * + * This can be used to trace coroutine code. Note that all usages of this method will appear + * under a single track. + */ + @JvmStatic + inline fun <T> traceAsync(method: String, block: () -> T): T = + traceAsync(DEFAULT_TRACK_NAME, method, block) + + /** + * Creates an async slice in a track with [trackName] while [block] runs. + * + * This can be used to trace coroutine code. [method] will be the name of the slice, + * [trackName] of the track. The track is one of the rows visible in a perfetto trace inside + * the app process. + */ + @JvmStatic + inline fun <T> traceAsync(trackName: String, method: String, block: () -> T): T { + val cookie = lastCookie.incrementAndGet() + Trace.asyncTraceForTrackBegin(Trace.TRACE_TAG_APP, trackName, method, cookie) + try { + return block() + } finally { + Trace.asyncTraceForTrackEnd(Trace.TRACE_TAG_APP, trackName, cookie) + } + } + + /** + * Convenience function for calling [CoroutineScope.launch] with [traceCoroutine] enable + * tracing. + * + * @see traceCoroutine + */ + inline fun CoroutineScope.launch( + crossinline spanName: () -> String, + context: CoroutineContext = EmptyCoroutineContext, + // TODO(b/306457056): DO NOT pass CoroutineStart; doing so will regress .odex size + crossinline block: suspend CoroutineScope.() -> Unit + ): Job = launch(context) { traceCoroutine(spanName) { block() } } + + /** + * Convenience function for calling [CoroutineScope.launch] with [traceCoroutine] enable + * tracing. + * + * @see traceCoroutine + */ + inline fun CoroutineScope.launch( + spanName: String, + context: CoroutineContext = EmptyCoroutineContext, + // TODO(b/306457056): DO NOT pass CoroutineStart; doing so will regress .odex size + crossinline block: suspend CoroutineScope.() -> Unit + ): Job = launch(context) { traceCoroutine(spanName) { block() } } + + /** + * Convenience function for calling [CoroutineScope.async] with [traceCoroutine] enable + * tracing + * + * @see traceCoroutine + */ + inline fun <T> CoroutineScope.async( + crossinline spanName: () -> String, + context: CoroutineContext = EmptyCoroutineContext, + // TODO(b/306457056): DO NOT pass CoroutineStart; doing so will regress .odex size + crossinline block: suspend CoroutineScope.() -> T + ): Deferred<T> = async(context) { traceCoroutine(spanName) { block() } } + + /** + * Convenience function for calling [CoroutineScope.async] with [traceCoroutine] enable + * tracing. + * + * @see traceCoroutine + */ + inline fun <T> CoroutineScope.async( + spanName: String, + context: CoroutineContext = EmptyCoroutineContext, + // TODO(b/306457056): DO NOT pass CoroutineStart; doing so will regress .odex size + crossinline block: suspend CoroutineScope.() -> T + ): Deferred<T> = async(context) { traceCoroutine(spanName) { block() } } + + /** + * Convenience function for calling [runBlocking] with [traceCoroutine] to enable tracing. + * + * @see traceCoroutine + */ + inline fun <T> runBlocking( + crossinline spanName: () -> String, + context: CoroutineContext, + crossinline block: suspend () -> T + ): T = runBlocking(context) { traceCoroutine(spanName) { block() } } + + /** + * Convenience function for calling [runBlocking] with [traceCoroutine] to enable tracing. + * + * @see traceCoroutine + */ + inline fun <T> runBlocking( + spanName: String, + context: CoroutineContext, + crossinline block: suspend CoroutineScope.() -> T + ): T = runBlocking(context) { traceCoroutine(spanName) { block() } } + + /** + * Convenience function for calling [withContext] with [traceCoroutine] to enable tracing. + * + * @see traceCoroutine + */ + suspend inline fun <T> withContext( + spanName: String, + context: CoroutineContext, + crossinline block: suspend CoroutineScope.() -> T + ): T = withContext(context) { traceCoroutine(spanName) { block() } } + + /** + * Convenience function for calling [withContext] with [traceCoroutine] to enable tracing. + * + * @see traceCoroutine + */ + suspend inline fun <T> withContext( + crossinline spanName: () -> String, + context: CoroutineContext, + crossinline block: suspend CoroutineScope.() -> T + ): T = withContext(context) { traceCoroutine(spanName) { block() } } + + /** + * A hacky way to propagate the value of the COROUTINE_TRACING flag for static usage in this + * file. It should only every be set to true during startup. Once true, it cannot be set to + * false again. + */ + var coroutineTracingIsEnabled = false + set(v) { + if (v) field = true + } + + /** + * Traces a section of work of a `suspend` [block]. The trace sections will appear on the + * thread that is currently executing the [block] of work. If the [block] is suspended, all + * trace sections added using this API will end until the [block] is resumed, which could + * happen either on this thread or on another thread. If a child coroutine is started, it + * will inherit the trace sections of its parent. The child will continue to print these + * trace sections whether or not the parent coroutine is still running them. + * + * The current [CoroutineContext] must have a [TraceContextElement] for this API to work. + * Otherwise, the trace sections will be dropped. + * + * For example, in the following trace, Thread #1 ran some work, suspended, then continued + * working on Thread #2. Meanwhile, Thread #2 created a new child coroutine which inherited + * its trace sections. Then, the original coroutine resumed on Thread #1 before ending. + * Meanwhile Thread #3 is still printing trace sections from its parent because they were + * copied when it was created. There is no way for the parent to communicate to the child + * that it marked these slices as completed. While this might seem counterintuitive, it + * allows us to pinpoint the origin of the child coroutine's work. + * + * ``` + * Thread #1 | [==== Slice A ====] [==== Slice A ====] + * | [==== B ====] [=== B ===] + * -------------------------------------------------------------------------------------- + * Thread #2 | [====== Slice A ======] + * | [========= B =========] + * | [===== C ======] + * -------------------------------------------------------------------------------------- + * Thread #3 | [== Slice A ==] [== Slice A ==] + * | [===== B =====] [===== B =====] + * | [===== C =====] [===== C =====] + * | [=== D ===] + * ``` + * + * @param name The name of the code section to appear in the trace + * @see endSlice + * @see traceCoroutine + */ + @OptIn(ExperimentalCoroutinesApi::class) + suspend inline fun <T> traceCoroutine( + spanName: Lazy<String>, + crossinline block: suspend () -> T + ): T { + // 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(spanName) + val coroutineSpanCookie = tracer?.beginSpan(spanName.value) ?: INVALID_SPAN + + // For now, also trace to "AsyncTraces". This will allow us to verify the correctness + // of the COROUTINE_TRACING feature flag. + val asyncTraceCookie = + if (Trace.isTagEnabled(Trace.TRACE_TAG_APP)) + Random.nextInt(FIRST_VALID_SPAN, Int.MAX_VALUE) + else INVALID_SPAN + if (asyncTraceCookie != INVALID_SPAN) { + Trace.asyncTraceForTrackBegin( + Trace.TRACE_TAG_APP, + DEFAULT_TRACK_NAME, + spanName.value, + asyncTraceCookie + ) + } + try { + return block() + } finally { + if (asyncTraceCookie != INVALID_SPAN) { + Trace.asyncTraceForTrackEnd( + Trace.TRACE_TAG_APP, + DEFAULT_TRACK_NAME, + asyncTraceCookie + ) + } + tracer?.endSpan(coroutineSpanCookie) + } + } + + @OptIn(ExperimentalCoroutinesApi::class) + suspend fun getTraceData(spanName: Lazy<String>): TraceData? { + if (!coroutineTracingIsEnabled) { + logVerbose("Experimental flag COROUTINE_TRACING is off", spanName) + } else if (coroutineContext[TraceContextElement] == null) { + logVerbose("Current CoroutineContext is missing TraceContextElement", spanName) + } else { + return threadLocalTrace.get().also { + if (it == null) logVerbose("ThreadLocal TraceData is null", spanName) + } + } + return null + } + + private fun logVerbose(logMessage: String, spanName: Lazy<String>) { + if (DEBUG_COROUTINE_TRACING && Log.isLoggable(TAG, Log.VERBOSE)) { + Log.v(TAG, "$logMessage. Dropping trace section: \"${spanName.value}\"") + } + } + + /** @see traceCoroutine */ + suspend inline fun <T> traceCoroutine( + spanName: String, + crossinline block: suspend () -> T + ): T = traceCoroutine(lazyOf(spanName)) { block() } + + /** @see traceCoroutine */ + suspend inline fun <T> traceCoroutine( + crossinline spanName: () -> String, + crossinline block: suspend () -> T + ): T = traceCoroutine(lazy(LazyThreadSafetyMode.PUBLICATION) { spanName() }) { block() } + + /** + * Writes a trace message to indicate that a given section of code has begun running __on + * the current thread__. This must be followed by a corresponding call to [endSlice] in a + * reasonably short amount of time __on the same thread__ (i.e. _before_ the thread becomes + * idle again and starts running other, unrelated work). + * + * Calls to [beginSlice] and [endSlice] may be nested, and they will render in Perfetto as + * follows: + * ``` + * Thread #1 | [==========================] + * | [==============] + * | [====] + * ``` + * + * This function is provided for convenience to wrap a call to [Trace.traceBegin], which is + * more verbose to call than [Trace.beginSection], but has the added benefit of not throwing + * an [IllegalArgumentException] if the provided string is longer than 127 characters. We + * use the term "slice" instead of "section" to be consistent with Perfetto. + * + * # Avoiding malformed traces + * + * Improper usage of this API will lead to malformed traces with long slices that sometimes + * never end. This will look like the following: + * ``` + * Thread #1 | [===================================================================== ... + * | [==============] [====================================== ... + * | [=======] [======] [===================== ... + * | [=======] + * ``` + * + * To avoid this, [beginSlice] and [endSlice] should never be called from `suspend` blocks + * (instead, use [traceCoroutine] for tracing suspending functions). While it would be + * technically okay to call from a suspending function if that function were to only wrap + * non-suspending blocks with [beginSlice] and [endSlice], doing so is risky because suspend + * calls could be mistakenly added to that block as the code is refactored. + * + * Additionally, it is _not_ okay to call [beginSlice] when registering a callback and match + * it with a call to [endSlice] inside that callback, even if the callback runs on the same + * thread. Doing so would cause malformed traces because the [beginSlice] wasn't closed + * before the thread became idle and started running unrelated work. + * + * @param sliceName The name of the code section to appear in the trace + * @see endSlice + * @see traceCoroutine + */ + fun beginSlice(sliceName: String) { + Trace.traceBegin(Trace.TRACE_TAG_APP, sliceName) + } + + /** + * Writes a trace message to indicate that a given section of code has ended. This call must + * be preceded by a corresponding call to [beginSlice]. See [beginSlice] for important + * information regarding usage. + * + * @see beginSlice + * @see traceCoroutine + */ + fun endSlice() { + Trace.traceEnd(Trace.TRACE_TAG_APP) + } + + /** + * Writes a trace message indicating that an instant event occurred on the current thread. + * Unlike slices, instant events have no duration and do not need to be matched with another + * call. Perfetto will display instant events using an arrow pointing to the timestamp they + * occurred: + * ``` + * Thread #1 | [==============] [======] + * | [====] ^ + * | ^ + * ``` + * + * @param eventName The name of the event to appear in the trace. + */ + fun instant(eventName: String) { + Trace.instant(Trace.TRACE_TAG_APP, eventName) + } + + /** + * Writes a trace message indicating that an instant event occurred on the given track. + * Unlike slices, instant events have no duration and do not need to be matched with another + * call. Perfetto will display instant events using an arrow pointing to the timestamp they + * occurred: + * ``` + * Async | [==============] [======] + * Track | [====] ^ + * Name | ^ + * ``` + * + * @param trackName The track where the event should appear in the trace. + * @param eventName The name of the event to appear in the trace. + */ + fun instantForTrack(trackName: String, eventName: String) { + Trace.instantForTrack(Trace.TRACE_TAG_APP, trackName, eventName) + } + } +} |