Skip to content

Instantly share code, notes, and snippets.

@psteiger
Last active April 13, 2023 00:27
Show Gist options
  • Save psteiger/5148fcce0d34b21bd8ba3b58d08095fe to your computer and use it in GitHub Desktop.
Save psteiger/5148fcce0d34b21bd8ba3b58d08095fe to your computer and use it in GitHub Desktop.
Short example of how continuation duration differs from coroutine duration.
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