Kotlin Coroutines - How does a delay within a loop can be completed so fast

Question

I am trying to run the following code.

I see in console about 8 worker threads are created and the printThread method after delay in delayNonBlockingSumOfNumbers() is executed parallely among different threads. I couldn't understand how the whole operation gets completed in 1-2 seconds.

I believe that a 1 second delay would actually be applied to a certain number. To be precise, 8 active threads running concurrently so total delay time would be 100000 iterations/8 Threads ~ 12500 iterations/thread or seconds.

My question is why/how so fast. And what has happened to multiple delay blocks, please clarify my understanding, if its not right.

I see coroutines are considered as lightweight threads,

does this mean a thread can simultaneously process multiple delay executions? Why I say this is because, the output displays the same thread is being used in execution multiple times like this

if its so, how can I debug or print the execution process of each suspended block that runs delaying execution, just like we do for threads viz. Thread.currentThread().name.

If I would have used Thread.sleep(1000) instead of delay, and had printed the thread, the output would display a 1 second difference between each execution. Similarly, how should I display a similar output from a coroutine execution where I can see the actual delay being processed?

fun delayNonBlockingSumOfNumbers(){

  printThread("Start of delayNonBlockingSumOfNumbers()")
  val deferredList = (1..100000).map {
    GlobalScope.async {
        //printThread("In Async Before Index $it")
        val timetaken:Long = 1000
        delay(timetaken)
        printThread("In Async After Delay Index $it time is -> $timetaken")
        it
    }
  }
 runBlocking {
    val sum = deferredList.sumBy { it.await() }
    printThread("End of delayNonBlockingSumOfNumbers(), sum = $sum")
 }
}

fun printThread(message:String){
  println("$message ${Thread.currentThread().name} ${Instant.now()}")
}

fun main(){
 delayNonBlockingSumOfNumbers()
 Thread.sleep(20_000)
 printThread("End of ")
}

Output: with the size of 1_000_000, seeing just a 3 second difference

Answer 1

how can I debug or print the execution process of each suspended block that runs delaying execution, just like we do for threads viz. Thread.currentThread().name

All you have to do is enable the coroutine debug mode. As per the documentation, the easiest way to do it is with the -ea JVM switch.

If you run the following with -ea:

fun main() {
    measureTimeMillis {
        runBlocking {
            (1..4).forEach {
                launch {
                    println("$it, delaying in ${Thread.currentThread().name}")
                    delay(1000)
                    println("$it, done in ${Thread.currentThread().name}")
                }
            }
        }
    }.also {
        println("Took $it ms")
    }
}

you should see output like this:

1, delaying in main @coroutine#2
2, delaying in main @coroutine#3
3, delaying in main @coroutine#4
4, delaying in main @coroutine#5
1, done in main @coroutine#2
2, done in main @coroutine#3
3, done in main @coroutine#4
4, done in main @coroutine#5
Took 1099 ms

what has happened to multiple delay blocks

You started 100,000 concurrent coroutines, all of them concurrently spent their 1 second of time sleeping, and then all of them woke up after 1 second, completing your test. This is exactly the same behavior you should expect from starting 100,000 threads and making them sleep.

Just like a thread doesn't occupy a CPU core while sleeping, so a coroutine doesn't occupy a thread while sleeping.

Answer 2

See this part of your code:

(1..100000).map {
    GlobalScope.async {
    //...
    }
}

so you are launching a new async coroutine for each of your 100000 elements. That is why your delays won't accumulate.