For full text search please use the '?' prefix. e.g. ? Onboarding

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 of Thread.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