CoRoutines do-not-play-nice-with Thread.sleep
In this example we show how CoRoutine do not play well with Thread.sleep
and how to fix it. (causing sequential execution of parallel co-rotuines)
Example:
package com.glassthought.sandbox
import gt.sandbox.util.output.Out
import kotlinx.coroutines.*
import kotlinx.coroutines.sync.Mutex
import kotlinx.coroutines.sync.withLock
val out = Out.standard()
suspend fun slowFunc() {
//delay(1000)
Thread.sleep(1000)
out.println("Slept for 1 second now I am done.")
}
fun main() = runBlocking {
// Launch coroutines
coroutineScope {
val jobs = (1..10).map {
launch {
out.println("Launching job $it")
slowFunc()
}
}
jobs.forEach { it.join() } // Wait for all coroutines to complete
}
out.println("End of main")
}
Command to reproduce:
gt.sandbox.checkout.commit c4c513e7ee932d7c531d \
&& cd "${GT_SANDBOX_REPO}" \
&& cmd.run.announce "./gradlew run"
Recorded output of command:
Output
> Task :app:checkKotlinGradlePluginConfigurationErrors SKIPPED
> Task :app:processResources NO-SOURCE
> Task :app:compileKotlin
> Task :app:compileJava NO-SOURCE
> Task :app:classes UP-TO-DATE
> Task :app:run
[2024-11-11T04:46:04.694149Z][elapsed-since-start: 42ms][tname:main/tid:1] Launching job 1
[2024-11-11T04:46:05.719155Z][elapsed-since-start: 1058ms][tname:main/tid:1] Slept for 1 second now I am done.
[2024-11-11T04:46:05.723650Z][elapsed-since-start: 1062ms][tname:main/tid:1] Launching job 2
[2024-11-11T04:46:06.724579Z][elapsed-since-start: 2063ms][tname:main/tid:1] Slept for 1 second now I am done.
[2024-11-11T04:46:06.724909Z][elapsed-since-start: 2063ms][tname:main/tid:1] Launching job 3
[2024-11-11T04:46:07.730109Z][elapsed-since-start: 3069ms][tname:main/tid:1] Slept for 1 second now I am done.
[2024-11-11T04:46:07.731408Z][elapsed-since-start: 3070ms][tname:main/tid:1] Launching job 4
[2024-11-11T04:46:08.734049Z][elapsed-since-start: 4073ms][tname:main/tid:1] Slept for 1 second now I am done.
[2024-11-11T04:46:08.734636Z][elapsed-since-start: 4073ms][tname:main/tid:1] Launching job 5
[2024-11-11T04:46:09.736674Z][elapsed-since-start: 5075ms][tname:main/tid:1] Slept for 1 second now I am done.
[2024-11-11T04:46:09.737790Z][elapsed-since-start: 5076ms][tname:main/tid:1] Launching job 6
[2024-11-11T04:46:10.738891Z][elapsed-since-start: 6078ms][tname:main/tid:1] Slept for 1 second now I am done.
[2024-11-11T04:46:10.739636Z][elapsed-since-start: 6078ms][tname:main/tid:1] Launching job 7
[2024-11-11T04:46:11.743111Z][elapsed-since-start: 7082ms][tname:main/tid:1] Slept for 1 second now I am done.
[2024-11-11T04:46:11.744012Z][elapsed-since-start: 7083ms][tname:main/tid:1] Launching job 8
[2024-11-11T04:46:12.748373Z][elapsed-since-start: 8087ms][tname:main/tid:1] Slept for 1 second now I am done.
[2024-11-11T04:46:12.748973Z][elapsed-since-start: 8087ms][tname:main/tid:1] Launching job 9
[2024-11-11T04:46:13.750204Z][elapsed-since-start: 9089ms][tname:main/tid:1] Slept for 1 second now I am done.
[2024-11-11T04:46:13.750833Z][elapsed-since-start: 9089ms][tname:main/tid:1] Launching job 10
[2024-11-11T04:46:14.755881Z][elapsed-since-start:10095ms][tname:main/tid:1] Slept for 1 second now I am done.
[2024-11-11T04:46:14.758462Z][elapsed-since-start:10097ms][tname:main/tid:1] End of main
BUILD SUCCESSFUL in 11s
2 actionable tasks: 2 executed
Why sequential execution is caused?
- In this example System Thread is shared between coroutines and blocking it with
Thread.sleep
will block all coroutines.
How to fix:
- Use
delay
instead ofThread.sleep
to avoid blocking the System Thread.
Example with Delay:
suspend fun slowFunc() {
delay(1000)
// Thread.sleep(1000)
out.println("Slept for 1 second now I am done.")
}
Command to reproduce:
gt.sandbox.checkout.commit cdbe9840224ed96267ae \
&& cd "${GT_SANDBOX_REPO}" \
&& cmd.run.announce "./gradlew run"
Recorded output of command:
> Task :app:checkKotlinGradlePluginConfigurationErrors SKIPPED
> Task :app:compileKotlin UP-TO-DATE
> Task :app:compileJava NO-SOURCE
> Task :app:processResources NO-SOURCE
> Task :app:classes UP-TO-DATE
> Task :app:run
[2024-11-11T04:49:28.790352Z][elapsed-since-start: 43ms][tname:main/tid:1] Launching job 1
[2024-11-11T04:49:28.811079Z][elapsed-since-start: 55ms][tname:main/tid:1] Launching job 2
[2024-11-11T04:49:28.811226Z][elapsed-since-start: 55ms][tname:main/tid:1] Launching job 3
[2024-11-11T04:49:28.811311Z][elapsed-since-start: 55ms][tname:main/tid:1] Launching job 4
[2024-11-11T04:49:28.811409Z][elapsed-since-start: 55ms][tname:main/tid:1] Launching job 5
[2024-11-11T04:49:28.811498Z][elapsed-since-start: 55ms][tname:main/tid:1] Launching job 6
[2024-11-11T04:49:28.811582Z][elapsed-since-start: 55ms][tname:main/tid:1] Launching job 7
[2024-11-11T04:49:28.811663Z][elapsed-since-start: 55ms][tname:main/tid:1] Launching job 8
[2024-11-11T04:49:28.811742Z][elapsed-since-start: 55ms][tname:main/tid:1] Launching job 9
[2024-11-11T04:49:28.811829Z][elapsed-since-start: 55ms][tname:main/tid:1] Launching job 10
[2024-11-11T04:49:29.813226Z][elapsed-since-start: 1057ms][tname:main/tid:1] Slept for 1 second now I am done.
[2024-11-11T04:49:29.815726Z][elapsed-since-start: 1059ms][tname:main/tid:1] Slept for 1 second now I am done.
[2024-11-11T04:49:29.816005Z][elapsed-since-start: 1060ms][tname:main/tid:1] Slept for 1 second now I am done.
[2024-11-11T04:49:29.816209Z][elapsed-since-start: 1060ms][tname:main/tid:1] Slept for 1 second now I am done.
[2024-11-11T04:49:29.816410Z][elapsed-since-start: 1060ms][tname:main/tid:1] Slept for 1 second now I am done.
[2024-11-11T04:49:29.816620Z][elapsed-since-start: 1060ms][tname:main/tid:1] Slept for 1 second now I am done.
[2024-11-11T04:49:29.816787Z][elapsed-since-start: 1060ms][tname:main/tid:1] Slept for 1 second now I am done.
[2024-11-11T04:49:29.816961Z][elapsed-since-start: 1060ms][tname:main/tid:1] Slept for 1 second now I am done.
[2024-11-11T04:49:29.817121Z][elapsed-since-start: 1061ms][tname:main/tid:1] Slept for 1 second now I am done.
[2024-11-11T04:49:29.817295Z][elapsed-since-start: 1061ms][tname:main/tid:1] Slept for 1 second now I am done.
[2024-11-11T04:49:29.818658Z][elapsed-since-start: 1062ms][tname:main/tid:1] End of main
BUILD SUCCESSFUL in 1s
2 actionable tasks: 1 executed, 1 up-to-date
Backlinks