Loading tracinglib/README.md 0 → 100644 +112 −0 Original line number Diff line number Diff line # Coroutine Tracing This library contains utilities for tracing coroutines. Coroutines cannot normally be traced using the `android.os.Trace` APIs because it will often lead to malformed trace sections. This is because each `Trace.beginSection` must have a matching `Trace.endSection` on the same thread before the scope is finished, so if they are used around a suspend point, the trace section will remain open while other unrelated work executes. It could even remain open indefinitely if the coroutine is canceled. To address this, we introduce a function `traceCoroutine("name") {}` that can be used for tracing sections of coroutine code. When invoked, a trace section with the given name will start immediately, and its name will also be written to an object in the current `CoroutineContext` used for coroutine-local storage. When the coroutine suspends, all trace sections will end immediately. When resumed, the coroutine will read the names of the previous sections from coroutine-local storage, and it will begin the sections again. For example, the following coroutine code will be traced as follows: ``` traceCoroutine("Slice A") { println("Start") delay(10) println("End") } ``` ``` Thread #1 | [==== Slice ====] [==== Slice ====] ^ "Start" printed ^ "End" printed ``` If multiple threads are used, it would be as follows: ``` traceCoroutine("Slice") { println("Start") delay(10) withContext(backgroundThread) { println("End") } } ``` ``` Thread #1 | [==== Slice ====] | ^ "Start" printed ----------+--------------------------------------------------------- Thread #2 | [==== Slice ====] ^ "End" printed ``` This library also provides wrappers for some of the coroutine functions provided in the `kotlinx.coroutines.*` package. For example, instead of: `launch { traceCoroutine("my-launch") { /* block */ } }`, you can instead write: `launch("my-launch") { /* block */ }`. It also provides a wrapper for tracing Flow emissions. For example, ``` val coldFlow = flow { emit(1) emit(2) emit(3) }.withTraceName("my-flow") coldFlow.collect { println(it) delay(10) } ``` Would be traced as follows: ``` Thread #1 | [=== my-flow:collect ===] [=== my-flow:collect ===] [=== my-flow:collect ===] | [== my-flow:emit ==] [== my-flow:emit ==] [== my-flow:emit ==] ``` # Building and Running ## Host Tests Host tests are implemented in `tracinglib-host-test`. To run the host tests: ``` atest tracinglib-host-test ``` ## Feature Flag Coroutine tracing is flagged off by default. To enable coroutine tracing on a device, flip the flag and restart the user-space system: ``` adb shell device_config override systemui com.android.systemui.coroutine_tracing true adb shell am restart ``` ## Demo App Build and install the app using Soong and adevice: ``` adevice track CoroutineTracingDemoApp m CoroutineTracingDemoApp adevice update ``` Then, open the app and tap an experiment to run it. The experiments run in the background. To see the effects of what coroutine tracing is doing, you will need to capture a Perfetto trace. The [`coroutine_tracing` flag](#feature-flag) will need to be enabled for coroutine trace sections to work. tracinglib/demo/README.mddeleted 100644 → 0 +0 −5 Original line number Diff line number Diff line # Building and Running Build and install the app using Soong and adevice. Then, tap an experiment to run it. The experiments run in the background, so to see what it is doing you will neeed to capture a perfetto trace. tracinglib/demo/src/com/android/app/tracing/demo/ApplicationComponent.kt +35 −7 Original line number Diff line number Diff line Loading @@ -15,6 +15,10 @@ */ package com.android.app.tracing.demo import android.os.Handler import android.os.HandlerThread import android.os.Looper import android.os.Trace import com.android.app.tracing.coroutines.createCoroutineTracingContext import com.android.app.tracing.demo.experiments.CollectFlow import com.android.app.tracing.demo.experiments.CombineDeferred Loading @@ -35,10 +39,9 @@ import javax.inject.Qualifier import javax.inject.Singleton import kotlin.annotation.AnnotationRetention.RUNTIME import kotlin.coroutines.CoroutineContext import kotlinx.coroutines.DelicateCoroutinesApi import kotlinx.coroutines.CoroutineScope import kotlinx.coroutines.Dispatchers import kotlinx.coroutines.ExperimentalCoroutinesApi import kotlinx.coroutines.newSingleThreadContext import kotlinx.coroutines.android.asCoroutineDispatcher @Qualifier @MustBeDocumented @Retention(RUNTIME) annotation class Main Loading @@ -52,6 +55,8 @@ import kotlinx.coroutines.newSingleThreadContext @Qualifier @MustBeDocumented @Retention(RUNTIME) annotation class FixedThread2 @Qualifier @MustBeDocumented @Retention(RUNTIME) annotation class ExperimentLauncherThread @Qualifier @MustBeDocumented @Retention(RUNTIME) annotation class Tracer @Module Loading Loading @@ -80,24 +85,37 @@ class ConcurrencyModule { return Dispatchers.Unconfined + tracerContext } @OptIn(ExperimentalCoroutinesApi::class, DelicateCoroutinesApi::class) @Provides @Singleton @FixedThread1 fun provideFixedThread1CoroutineContext( @Tracer tracerContext: CoroutineContext ): CoroutineContext { return newSingleThreadContext("FixedThread #1") + tracerContext val looper = startThreadWithLooper("FixedThread #1") return Handler(looper).asCoroutineDispatcher("FixedCoroutineDispatcher #1") + tracerContext } @OptIn(ExperimentalCoroutinesApi::class, DelicateCoroutinesApi::class) @Provides @Singleton @FixedThread2 fun provideFixedThread2CoroutineContext( @Tracer tracerContext: CoroutineContext ): CoroutineContext { return newSingleThreadContext("FixedThread #2") + tracerContext val looper = startThreadWithLooper("FixedThread #2") return Handler(looper).asCoroutineDispatcher("FixedCoroutineDispatcher #2") + tracerContext } @Provides @Singleton @ExperimentLauncherThread fun provideExperimentLauncherCoroutineScope( @Tracer tracerContext: CoroutineContext ): CoroutineScope { val looper = startThreadWithLooper("Experiment Launcher Thread") return CoroutineScope( Handler(looper).asCoroutineDispatcher("Experiment Launcher CoroutineDispatcher") + tracerContext ) } @Provides Loading Loading @@ -151,4 +169,14 @@ interface ExperimentModule { interface ApplicationComponent { /** Returns [Experiment]s that should be used with the application. */ @Singleton fun getAllExperiments(): Map<Class<*>, Provider<Experiment>> @Singleton @ExperimentLauncherThread fun getExperimentLauncherCoroutineScope(): CoroutineScope } private fun startThreadWithLooper(name: String): Looper { val thread = HandlerThread(name) thread.start() val looper = thread.looper looper.setTraceTag(Trace.TRACE_TAG_APP) return looper } tracinglib/demo/src/com/android/app/tracing/demo/MainActivity.kt +5 −9 Original line number Diff line number Diff line Loading @@ -26,30 +26,26 @@ import android.widget.TextView import com.android.app.tracing.TraceUtils.trace import com.android.app.tracing.demo.experiments.Experiment import kotlinx.coroutines.CancellationException import kotlinx.coroutines.CoroutineScope import kotlinx.coroutines.DelicateCoroutinesApi import kotlinx.coroutines.ExperimentalCoroutinesApi import kotlinx.coroutines.Job import kotlinx.coroutines.cancel import kotlinx.coroutines.launch import kotlinx.coroutines.newSingleThreadContext private const val TRACK_NAME = "Active experiments" class MainActivity : Activity() { @OptIn(ExperimentalCoroutinesApi::class, DelicateCoroutinesApi::class) val threadContext = newSingleThreadContext("Experiment launcher") private val allExperiments = lazy { (applicationContext as MainApplication).appComponent.getAllExperiments() } private val experimentLaunchScope = lazy { (applicationContext as MainApplication).appComponent.getExperimentLauncherCoroutineScope() } private var logContainer: ScrollView? = null private var loggerView: TextView? = null private fun <T : Experiment> createButtonForExperiment(demo: T): Button { val buttonCoroutineScope = CoroutineScope(threadContext) var launchCounter = 0 var job: Job? = null val className = demo::class.simpleName ?: "<unknown class>" Loading @@ -64,7 +60,7 @@ class MainActivity : Activity() { val experimentName = "$className #${launchCounter++}" trace("$className#onClick") { job?.let { trace("cancel") { it.cancel("Cancelled due to click") } } trace("launch") { job = buttonCoroutineScope.launch { demo.run() } } trace("launch") { job = experimentLaunchScope.value.launch { demo.run() } } trace("toast") { appendLine("$experimentName started") } job?.let { Trace.asyncTraceForTrackBegin( Loading tracinglib/demo/src/com/android/app/tracing/demo/experiments/CollectFlow.kt +45 −17 Original line number Diff line number Diff line Loading @@ -15,45 +15,73 @@ */ package com.android.app.tracing.demo.experiments import com.android.app.tracing.coroutines.flow.filter import com.android.app.tracing.coroutines.flow.flowOn import com.android.app.tracing.coroutines.flow.map import com.android.app.tracing.coroutines.flow.withTraceName import com.android.app.tracing.coroutines.launch import com.android.app.tracing.coroutines.traceCoroutine import com.android.app.tracing.demo.FixedThread1 import com.android.app.tracing.demo.FixedThread2 import javax.inject.Inject import javax.inject.Singleton import kotlin.coroutines.CoroutineContext import kotlinx.coroutines.coroutineScope import kotlinx.coroutines.delay import kotlinx.coroutines.flow.filter import kotlinx.coroutines.flow.flow import kotlinx.coroutines.flow.flowOn import kotlinx.coroutines.flow.map /** Util for introducing artificial delays to make the trace more readable for demo purposes. */ private fun blockCurrentThread(millis: Long) { Thread.sleep(millis) } @Singleton class CollectFlow @Inject constructor( @FixedThread1 private var fixedThreadContext1: CoroutineContext, @FixedThread1 private var fixedThreadContext2: CoroutineContext, @FixedThread2 private var fixedThreadContext2: CoroutineContext, ) : Experiment { override fun getDescription(): String = "Collect a cold flow with intermediate operators" private val numFlow = override suspend fun run(): Unit = coroutineScope { val numFlow = flow { for (n in 0..1000) { traceCoroutine("num-flow:delay(1)") { delay(1) } traceCoroutine("num-flow:emit($n)") { emit(n) } for (n in 0..4) { traceCoroutine("delay-and-emit for $n") { blockCurrentThread(10) delay(1) blockCurrentThread(10) emit(n) blockCurrentThread(10) delay(1) blockCurrentThread(10) } } } .withTraceName("flowOf numbers") .filter { blockCurrentThread(10) it % 2 == 0 } .withTraceName("num-flow") .filter { it % 2 == 0 } .map { it * 0.5 } .withTraceName("filter for even") .map { blockCurrentThread(10) it * 3 } .withTraceName("map 3x") .flowOn(fixedThreadContext2) .withTraceName("flowOn thread #2") override suspend fun run(): Unit = coroutineScope { launch("launch", fixedThreadContext1) { numFlow.collect { value -> traceCoroutine("got: $value") { delay(1) } } launch("launch on thread #1", fixedThreadContext1) { numFlow.collect { traceCoroutine("got: $it") { blockCurrentThread(10) delay(1) blockCurrentThread(10) } } } } } Loading
tracinglib/README.md 0 → 100644 +112 −0 Original line number Diff line number Diff line # Coroutine Tracing This library contains utilities for tracing coroutines. Coroutines cannot normally be traced using the `android.os.Trace` APIs because it will often lead to malformed trace sections. This is because each `Trace.beginSection` must have a matching `Trace.endSection` on the same thread before the scope is finished, so if they are used around a suspend point, the trace section will remain open while other unrelated work executes. It could even remain open indefinitely if the coroutine is canceled. To address this, we introduce a function `traceCoroutine("name") {}` that can be used for tracing sections of coroutine code. When invoked, a trace section with the given name will start immediately, and its name will also be written to an object in the current `CoroutineContext` used for coroutine-local storage. When the coroutine suspends, all trace sections will end immediately. When resumed, the coroutine will read the names of the previous sections from coroutine-local storage, and it will begin the sections again. For example, the following coroutine code will be traced as follows: ``` traceCoroutine("Slice A") { println("Start") delay(10) println("End") } ``` ``` Thread #1 | [==== Slice ====] [==== Slice ====] ^ "Start" printed ^ "End" printed ``` If multiple threads are used, it would be as follows: ``` traceCoroutine("Slice") { println("Start") delay(10) withContext(backgroundThread) { println("End") } } ``` ``` Thread #1 | [==== Slice ====] | ^ "Start" printed ----------+--------------------------------------------------------- Thread #2 | [==== Slice ====] ^ "End" printed ``` This library also provides wrappers for some of the coroutine functions provided in the `kotlinx.coroutines.*` package. For example, instead of: `launch { traceCoroutine("my-launch") { /* block */ } }`, you can instead write: `launch("my-launch") { /* block */ }`. It also provides a wrapper for tracing Flow emissions. For example, ``` val coldFlow = flow { emit(1) emit(2) emit(3) }.withTraceName("my-flow") coldFlow.collect { println(it) delay(10) } ``` Would be traced as follows: ``` Thread #1 | [=== my-flow:collect ===] [=== my-flow:collect ===] [=== my-flow:collect ===] | [== my-flow:emit ==] [== my-flow:emit ==] [== my-flow:emit ==] ``` # Building and Running ## Host Tests Host tests are implemented in `tracinglib-host-test`. To run the host tests: ``` atest tracinglib-host-test ``` ## Feature Flag Coroutine tracing is flagged off by default. To enable coroutine tracing on a device, flip the flag and restart the user-space system: ``` adb shell device_config override systemui com.android.systemui.coroutine_tracing true adb shell am restart ``` ## Demo App Build and install the app using Soong and adevice: ``` adevice track CoroutineTracingDemoApp m CoroutineTracingDemoApp adevice update ``` Then, open the app and tap an experiment to run it. The experiments run in the background. To see the effects of what coroutine tracing is doing, you will need to capture a Perfetto trace. The [`coroutine_tracing` flag](#feature-flag) will need to be enabled for coroutine trace sections to work.
tracinglib/demo/README.mddeleted 100644 → 0 +0 −5 Original line number Diff line number Diff line # Building and Running Build and install the app using Soong and adevice. Then, tap an experiment to run it. The experiments run in the background, so to see what it is doing you will neeed to capture a perfetto trace.
tracinglib/demo/src/com/android/app/tracing/demo/ApplicationComponent.kt +35 −7 Original line number Diff line number Diff line Loading @@ -15,6 +15,10 @@ */ package com.android.app.tracing.demo import android.os.Handler import android.os.HandlerThread import android.os.Looper import android.os.Trace import com.android.app.tracing.coroutines.createCoroutineTracingContext import com.android.app.tracing.demo.experiments.CollectFlow import com.android.app.tracing.demo.experiments.CombineDeferred Loading @@ -35,10 +39,9 @@ import javax.inject.Qualifier import javax.inject.Singleton import kotlin.annotation.AnnotationRetention.RUNTIME import kotlin.coroutines.CoroutineContext import kotlinx.coroutines.DelicateCoroutinesApi import kotlinx.coroutines.CoroutineScope import kotlinx.coroutines.Dispatchers import kotlinx.coroutines.ExperimentalCoroutinesApi import kotlinx.coroutines.newSingleThreadContext import kotlinx.coroutines.android.asCoroutineDispatcher @Qualifier @MustBeDocumented @Retention(RUNTIME) annotation class Main Loading @@ -52,6 +55,8 @@ import kotlinx.coroutines.newSingleThreadContext @Qualifier @MustBeDocumented @Retention(RUNTIME) annotation class FixedThread2 @Qualifier @MustBeDocumented @Retention(RUNTIME) annotation class ExperimentLauncherThread @Qualifier @MustBeDocumented @Retention(RUNTIME) annotation class Tracer @Module Loading Loading @@ -80,24 +85,37 @@ class ConcurrencyModule { return Dispatchers.Unconfined + tracerContext } @OptIn(ExperimentalCoroutinesApi::class, DelicateCoroutinesApi::class) @Provides @Singleton @FixedThread1 fun provideFixedThread1CoroutineContext( @Tracer tracerContext: CoroutineContext ): CoroutineContext { return newSingleThreadContext("FixedThread #1") + tracerContext val looper = startThreadWithLooper("FixedThread #1") return Handler(looper).asCoroutineDispatcher("FixedCoroutineDispatcher #1") + tracerContext } @OptIn(ExperimentalCoroutinesApi::class, DelicateCoroutinesApi::class) @Provides @Singleton @FixedThread2 fun provideFixedThread2CoroutineContext( @Tracer tracerContext: CoroutineContext ): CoroutineContext { return newSingleThreadContext("FixedThread #2") + tracerContext val looper = startThreadWithLooper("FixedThread #2") return Handler(looper).asCoroutineDispatcher("FixedCoroutineDispatcher #2") + tracerContext } @Provides @Singleton @ExperimentLauncherThread fun provideExperimentLauncherCoroutineScope( @Tracer tracerContext: CoroutineContext ): CoroutineScope { val looper = startThreadWithLooper("Experiment Launcher Thread") return CoroutineScope( Handler(looper).asCoroutineDispatcher("Experiment Launcher CoroutineDispatcher") + tracerContext ) } @Provides Loading Loading @@ -151,4 +169,14 @@ interface ExperimentModule { interface ApplicationComponent { /** Returns [Experiment]s that should be used with the application. */ @Singleton fun getAllExperiments(): Map<Class<*>, Provider<Experiment>> @Singleton @ExperimentLauncherThread fun getExperimentLauncherCoroutineScope(): CoroutineScope } private fun startThreadWithLooper(name: String): Looper { val thread = HandlerThread(name) thread.start() val looper = thread.looper looper.setTraceTag(Trace.TRACE_TAG_APP) return looper }
tracinglib/demo/src/com/android/app/tracing/demo/MainActivity.kt +5 −9 Original line number Diff line number Diff line Loading @@ -26,30 +26,26 @@ import android.widget.TextView import com.android.app.tracing.TraceUtils.trace import com.android.app.tracing.demo.experiments.Experiment import kotlinx.coroutines.CancellationException import kotlinx.coroutines.CoroutineScope import kotlinx.coroutines.DelicateCoroutinesApi import kotlinx.coroutines.ExperimentalCoroutinesApi import kotlinx.coroutines.Job import kotlinx.coroutines.cancel import kotlinx.coroutines.launch import kotlinx.coroutines.newSingleThreadContext private const val TRACK_NAME = "Active experiments" class MainActivity : Activity() { @OptIn(ExperimentalCoroutinesApi::class, DelicateCoroutinesApi::class) val threadContext = newSingleThreadContext("Experiment launcher") private val allExperiments = lazy { (applicationContext as MainApplication).appComponent.getAllExperiments() } private val experimentLaunchScope = lazy { (applicationContext as MainApplication).appComponent.getExperimentLauncherCoroutineScope() } private var logContainer: ScrollView? = null private var loggerView: TextView? = null private fun <T : Experiment> createButtonForExperiment(demo: T): Button { val buttonCoroutineScope = CoroutineScope(threadContext) var launchCounter = 0 var job: Job? = null val className = demo::class.simpleName ?: "<unknown class>" Loading @@ -64,7 +60,7 @@ class MainActivity : Activity() { val experimentName = "$className #${launchCounter++}" trace("$className#onClick") { job?.let { trace("cancel") { it.cancel("Cancelled due to click") } } trace("launch") { job = buttonCoroutineScope.launch { demo.run() } } trace("launch") { job = experimentLaunchScope.value.launch { demo.run() } } trace("toast") { appendLine("$experimentName started") } job?.let { Trace.asyncTraceForTrackBegin( Loading
tracinglib/demo/src/com/android/app/tracing/demo/experiments/CollectFlow.kt +45 −17 Original line number Diff line number Diff line Loading @@ -15,45 +15,73 @@ */ package com.android.app.tracing.demo.experiments import com.android.app.tracing.coroutines.flow.filter import com.android.app.tracing.coroutines.flow.flowOn import com.android.app.tracing.coroutines.flow.map import com.android.app.tracing.coroutines.flow.withTraceName import com.android.app.tracing.coroutines.launch import com.android.app.tracing.coroutines.traceCoroutine import com.android.app.tracing.demo.FixedThread1 import com.android.app.tracing.demo.FixedThread2 import javax.inject.Inject import javax.inject.Singleton import kotlin.coroutines.CoroutineContext import kotlinx.coroutines.coroutineScope import kotlinx.coroutines.delay import kotlinx.coroutines.flow.filter import kotlinx.coroutines.flow.flow import kotlinx.coroutines.flow.flowOn import kotlinx.coroutines.flow.map /** Util for introducing artificial delays to make the trace more readable for demo purposes. */ private fun blockCurrentThread(millis: Long) { Thread.sleep(millis) } @Singleton class CollectFlow @Inject constructor( @FixedThread1 private var fixedThreadContext1: CoroutineContext, @FixedThread1 private var fixedThreadContext2: CoroutineContext, @FixedThread2 private var fixedThreadContext2: CoroutineContext, ) : Experiment { override fun getDescription(): String = "Collect a cold flow with intermediate operators" private val numFlow = override suspend fun run(): Unit = coroutineScope { val numFlow = flow { for (n in 0..1000) { traceCoroutine("num-flow:delay(1)") { delay(1) } traceCoroutine("num-flow:emit($n)") { emit(n) } for (n in 0..4) { traceCoroutine("delay-and-emit for $n") { blockCurrentThread(10) delay(1) blockCurrentThread(10) emit(n) blockCurrentThread(10) delay(1) blockCurrentThread(10) } } } .withTraceName("flowOf numbers") .filter { blockCurrentThread(10) it % 2 == 0 } .withTraceName("num-flow") .filter { it % 2 == 0 } .map { it * 0.5 } .withTraceName("filter for even") .map { blockCurrentThread(10) it * 3 } .withTraceName("map 3x") .flowOn(fixedThreadContext2) .withTraceName("flowOn thread #2") override suspend fun run(): Unit = coroutineScope { launch("launch", fixedThreadContext1) { numFlow.collect { value -> traceCoroutine("got: $value") { delay(1) } } launch("launch on thread #1", fixedThreadContext1) { numFlow.collect { traceCoroutine("got: $it") { blockCurrentThread(10) delay(1) blockCurrentThread(10) } } } } }