Description
reproduction steps
(using Scala 2.12.12 or 2.13.3)
- clone a project from https://github.com/OndrejSpanel/ParLoopAndFuture
- run the Main class using JDK 11.0.4
problem
Observe the message "Suspicious background duration ..." being printed multiple times. This messages shows that a problem with a parallel foreach scheduling has been detected, namely that a long-duration future created from the parallel foreach has blocked the foreach executtion. This happens both with Scala 2.12.12 and Scala 2.13.3 running on JDK 11.0.4. It does not happen when running on JDK / JRE 8. It seems to happen intermittently, probably depending on exact timing of the Future call relative the to parallel collection tasks execution.
The foreach should normally terminate in much less than 200 ms, as 50 tasks are executed, each of them taking 2 ms. Once it takes more than 200 ms, it shows there is a scheduling problem with the slow future blocking the parallel collection tasks.
Following JFR screenshot shows the thread scheduling once the issue is seen (you can also see normals iterations without the issue):
My configuration is Windows 10 x64 build 2004, Intel i7 / 4x core.
The code demonstrating the issue is https://github.com/OndrejSpanel/ParLoopAndFuture/blob/c2f4d1b6b155217d8f8111f58e6a7c9337f36619/src/main/scala/com/github/ondrejspanel/parFuture/Main.scala#L1-L45
package com.github.ondrejspanel.parFuture
import scala.concurrent.Future
import scala.concurrent.ExecutionContext.Implicits.global
object Main {
def hotSleep(ms: Int): Unit = {
val now = System.currentTimeMillis()
while (System.currentTimeMillis() < now + ms) {}
}
def main(args: Array[String]): Unit = {
val stateCount = 50
val state = (0 until stateCount).par
val triggerIssue = true
(0 until 1000).foreach { i =>
hotSleep(25)
val innerScopeBeg = System.currentTimeMillis()
if (!triggerIssue) {
Future {
hotSleep(205)
}
}
state.foreach { x =>
if (triggerIssue && x == 0) {
Future {
hotSleep(205)
}
}
hotSleep(2)
}
val innerScopeEnd = System.currentTimeMillis()
val duration = innerScopeEnd - innerScopeBeg
if (duration >= 200) {
println(s"Suspicious background duration $duration")
}
}
}
}