Last active
April 13, 2023 00:27
-
-
Save psteiger/5148fcce0d34b21bd8ba3b58d08095fe to your computer and use it in GitHub Desktop.
Short example of how continuation duration differs from coroutine duration.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
import kotlinx.coroutines.* | |
import kotlin.coroutines.* | |
import kotlin.system.* | |
/** Wraps original dispatcher, so we can wrap the continuations. */ | |
class Monitor( | |
private val interceptor: ContinuationInterceptor | |
) : AbstractCoroutineContextElement(ContinuationInterceptor), ContinuationInterceptor { | |
override fun <T> interceptContinuation(continuation: Continuation<T>): Continuation<T> = | |
interceptor.interceptContinuation(MeasuredContinuation(continuation)) | |
override fun releaseInterceptedContinuation(continuation: Continuation<*>) { | |
interceptor.releaseInterceptedContinuation(continuation) | |
} | |
} | |
val ContinuationInterceptor.monitored get() = Monitor(this) | |
/** Wraps an original continuation, tracking the time it takes to complete. */ | |
class MeasuredContinuation<T>(val continuation: Continuation<T>): Continuation<T> { | |
override val context: CoroutineContext get() = continuation.context | |
override fun resumeWith(result: Result<T>) { | |
val time = measureTimeMillis { continuation.resumeWith(result) } | |
println("Continuation time $time") | |
} | |
} | |
/** The suspend fun we will be tracking. */ | |
suspend fun someSuspendFun() { | |
println("Starting suspend fun") // Continuation #1 | |
println("Delaying for 1s") // Continuation #1 | |
delay(1000) | |
println("Sleeping for 2s -- simulate thread busy for too long") // Continuation #2 | |
Thread.sleep(2000) // Continuation #2 | |
println("Delaying for 3s") // Continuation #2 | |
delay(3000) | |
println("Suspend fun done") // Continuation #3 | |
} | |
suspend fun main() { | |
// Measuring total coroutine duration. | |
val totalTime = measureTimeMillis { someSuspendFun() } | |
println(totalTime) | |
// Measuring each continuation duration. | |
withContext(Dispatchers.Default.monitored) { | |
someSuspendFun() | |
} | |
} | |
/* | |
Output for measuring the whole coroutine duration: | |
Starting suspend fun | |
Delaying for 1s | |
Sleeping for 2s -- simulate thread busy for too long | |
Delaying for 3s | |
Suspend fun done | |
6034 | |
Whole coroutine takes 6034ms. But of those ~6s, for 4 seconds it was suspended (`delay(1000)` and `delay(3000)`), so it was | |
not keeping a thread busy. | |
For the purposes of thread usage monitoring, we don't care about the duration of the coroutine, what we are actually | |
interested is in the duration of *each continuation*, which is the work coroutines do while not suspended. | |
Output for measuring each continuation duration: | |
Starting suspend fun | |
Delaying for 1s | |
Continuation time 1 | |
Sleeping for 2s -- simulate thread busy for too long | |
Delaying for 3s | |
Continuation time 2005 | |
Suspend fun done | |
Continuation time 1 | |
We see the first continuation (1) takes 1ms. The second continuation (2), however, occupies the thread for ~2s | |
(as it uses `Thread.sleep`). The next continuation (3) only occupies for an additional 1ms. | |
Note that the sum of the continuation duration in here is 2007ms, which is far less than the total coroutine duration which is | |
6034ms. Of those 6 seconds, for 4 seconds it was *suspended*, which does not occupy any thread resource. | |
Conclusion: When monitoring coroutines for the purpose of thread utilization, we should monitor *continuation* duration instead | |
of coroutine duration. Continuations are the *blocking pieces* that make up a coroutine. | |
*/ |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment