Deadlock with ScalaCheck 1.13.x, scalaz-concurrent, and Scala 2.12.0-RC2

[larsrh]

After trying to port remotely to Scala 2.12.x, I found that some of the tests involving scala.concurrent.Future weren't terminating. The most likely cause is a deadlock. The issue doesn't appear in Scala 2.10.x or 2.11.x, and also not when running ScalaCheck properties through ScalaTest. It only manifests when using the plain ScalaCheck runner and 2.12.0-RC2.

A small reproduction project, including instructions, can be found here.

As of now I'm unsure whether this is a problem with scalaz.concurrent.Task, scala.concurrent.Future, or ScalaCheck (or a combination thereof). I'm opening this issue so that others who might have the same problem can find it.

[larsrh]

Same result even with a different worker count:

> testOnly remotely.ResponseSpec -- -workers 2

deadlocks with w = 1 and 2

[viktorklang]

Thread dump? (logical or actual deadlock?)

[larsrh]

https://gist.github.com/larsrh/7745732685193f908b64b0fe466966db

[mpilquist]

This throws after 10 second delay at object initialization time:

object ResponseSpec extends Properties("Response") {
  property("stack safety") = {
    import ExecutionContext.Implicits.global
    val f = Future(1)
    Await.result(f, 10.seconds) == 1
  }
}

Not sure if it's related or not but seems suspicious. JStack shows the same/similar stack trace as the hang in the original ResponseSpec:

"scala-execution-context-global-9" #9 daemon prio=5 os_prio=31 tid=0x00007fd89d435000 nid=0x4d03 in Object.wait() [0x0000700001149000]
   java.lang.Thread.State: RUNNABLE
        at remotely.ResponseSpec$$$Lambda$19/1836797772.apply$mcI$sp(Unknown Source)
        at scala.runtime.java8.JFunction0$mcI$sp.apply(JFunction0$mcI$sp.java:12)
        at scala.concurrent.Future$.$anonfun$apply$1(Future.scala:653)
        at scala.concurrent.Future$$$Lambda$21/1206883981.apply(Unknown Source)
        at scala.util.Success.$anonfun$map$1(Try.scala:251)
        at scala.util.Success.map(Try.scala:209)
        at scala.concurrent.Future.$anonfun$map$1(Future.scala:287)
        at scala.concurrent.impl.Promise$KeptPromise$Successful$$Lambda$22/1525037790.apply(Unknown Source)
        at scala.concurrent.impl.Promise.liftedTree1$1(Promise.scala:29)
        at scala.concurrent.impl.Promise.$anonfun$transform$1(Promise.scala:29)
        at scala.concurrent.impl.Promise$KeptPromise$Successful$$Lambda$23/727001376.apply(Unknown Source)
        at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:60)
        at scala.concurrent.impl.ExecutionContextImpl$AdaptedForkJoinTask.exec(ExecutionContextImpl.scala:140)
        at java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:289)
        at java.util.concurrent.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1056)
        at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1692)
        at java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:157)

[viktorklang]

hmm, I don't understand. why is remotely in the stack trace if not in the
code?

Cheers,
√

On Oct 29, 2016 6:31 PM, "Michael Pilquist" notifications@github.com
wrote:

This throws after 10 second delay at object initialization time:

object ResponseSpec extends Properties("Response") {
property("stack safety") = {
import ExecutionContext.Implicits.global
val f = Future(1)
Await.result(f, 10.seconds) == 1
}
}

Not sure if it's related or not but seems suspicious. JStack shows the
same/similar stack trace as the hang in the original ResponseSpec:

"scala-execution-context-global-9" #9 daemon prio=5 os_prio=31 tid=0x00007fd89d435000 nid=0x4d03 in Object.wait() [0x0000700001149000]
java.lang.Thread.State: RUNNABLE
at remotely.ResponseSpec$$$Lambda$19/1836797772.apply$mcI$sp(Unknown Source)
at scala.runtime.java8.JFunction0$mcI$sp.apply(JFunction0$mcI$sp.java:12)
at scala.concurrent.Future$.$anonfun$apply$1(Future.scala:653)
at scala.concurrent.Future$$$Lambda$21/1206883981.apply(Unknown Source)
at scala.util.Success.$anonfun$map$1(Try.scala:251)
at scala.util.Success.map(Try.scala:209)
at scala.concurrent.Future.$anonfun$map$1(Future.scala:287)
at scala.concurrent.impl.Promise$KeptPromise$Successful$$Lambda$22/1525037790.apply(Unknown Source)
at scala.concurrent.impl.Promise.liftedTree1$1(Promise.scala:29)
at scala.concurrent.impl.Promise.$anonfun$transform$1(Promise.scala:29)
at scala.concurrent.impl.Promise$KeptPromise$Successful$$Lambda$23/727001376.apply(Unknown Source)
at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:60)
at scala.concurrent.impl.ExecutionContextImpl$AdaptedForkJoinTask.exec(ExecutionContextImpl.scala:140)
at java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:289)
at java.util.concurrent.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1056)
at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1692)
at java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:157)

—
You are receiving this because you commented.
Reply to this email directly, view it on GitHub
#290 (comment),
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAAqdwW_W-euLVJZ66nW2i4Mxh-sW-5Eks5q43S-gaJpZM4KkEq9
.

[mpilquist]

@viktorklang Only because the test class is in the "remotely" package.

Here's a further simplification which shows the same hang in jstack:

package remotely

import org.scalacheck._
import scala.concurrent.{Await,ExecutionContext,Future}
import scala.concurrent.duration._
import scala.util.{Success,Failure}
import java.util.concurrent.Executors

object ResponseSpec extends Properties("Response") {
  property("stack safety") = {
    implicit val ec = ExecutionContext.fromExecutor(Executors.newCachedThreadPool())
    Await.result(Future(1), 1000.seconds) == 1
  }
}

I think what's happening here is that when we run the tests via ScalaCheck, the properties are being instantiated as part of object initialization of ResponseSpec. However, we have a separate thread calling back in to ResponseSpec from the thread pool, and it looks like that thread spin-waits on ResponseSpec object initialization to complete (or otherwise blocks in a way that's not visible to JVM).

So overall, I don't think this is a bug, just an undesirable result of running futures from an object initializer.

[mpilquist]

One more simplification -- same hang here:

object Foo {
  import ExecutionContext.Implicits.global
  val x = Await.result(Future(1), 1000.seconds)
  def main(args: Array[String]) = println(x)
}

Dump:

2016-10-29 12:56:19
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.102-b14 mixed mode):

"Attach Listener" #10 daemon prio=9 os_prio=31 tid=0x00007fcc6c19b000 nid=0x360b waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"pool-1-thread-1" #9 prio=5 os_prio=31 tid=0x00007fcc6a58c000 nid=0x4d03 in Object.wait() [0x0000700001149000]
   java.lang.Thread.State: RUNNABLE
        at remotely.Foo$$$Lambda$12/60830820.apply$mcI$sp(Unknown Source)
        at scala.runtime.java8.JFunction0$mcI$sp.apply(JFunction0$mcI$sp.java:12)
        at scala.concurrent.Future$.$anonfun$apply$1(Future.scala:653)
        at scala.concurrent.Future$$$Lambda$13/1698156408.apply(Unknown Source)
        at scala.util.Success.$anonfun$map$1(Try.scala:251)
        at scala.util.Success.map(Try.scala:209)
        at scala.concurrent.Future.$anonfun$map$1(Future.scala:287)
        at scala.concurrent.impl.Promise$KeptPromise$Successful$$Lambda$14/913190639.apply(Unknown Source)
        at scala.concurrent.impl.Promise.liftedTree1$1(Promise.scala:29)
        at scala.concurrent.impl.Promise.$anonfun$transform$1(Promise.scala:29)
        at scala.concurrent.impl.Promise$KeptPromise$Successful$$Lambda$15/922151033.apply(Unknown Source)
        at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:60)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)

"Service Thread" #8 daemon prio=9 os_prio=31 tid=0x00007fcc6a029800 nid=0x4903 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread2" #7 daemon prio=9 os_prio=31 tid=0x00007fcc6b845800 nid=0x4703 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" #6 daemon prio=9 os_prio=31 tid=0x00007fcc6b833800 nid=0x4503 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #5 daemon prio=9 os_prio=31 tid=0x00007fcc6b832000 nid=0x4303 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=31 tid=0x00007fcc6b83c800 nid=0x320f runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=31 tid=0x00007fcc6b814800 nid=0x3003 in Object.wait() [0x000070000092e000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x0000000795588e98> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)

[adriaanm]

Yep, @mpilquist says it well. See also http://stackoverflow.com/questions/15176199/scala-parallel-collection-in-object-initializer-causes-a-program-to-hang/15176433#15176433. This was true before 2.12.

New in 2.12 is that locking behavior is now different when lambdas are involved, as the lambda body is lifted to a member of the enclosing class (and thus an invocation blocks on the object's initialization lock), instead of a method in a separate (anonymous) class.

[viktorklang]

Adrian,

this new behavior sounds plenty risky.

Cheers,
√

On Oct 29, 2016 7:57 PM, "Adriaan Moors" notifications@github.com wrote:

Yep, @mpilquist https://github.com/mpilquist says it well. See also
http://stackoverflow.com/questions/15176199/scala-
parallel-collection-in-object-initializer-causes-a-program-
to-hang/15176433#15176433. This was true before 2.12.

New in 2.12 is that locking behavior is now different when lambdas are
involved, as the lambda body is lifted to a member of the enclosing class
(and thus an invocation locks on the class's monitor), instead of a method
in a separate (anonymous) class.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
#290 (comment),
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAAqd-BDK_Jd7g0E4xhWKJRmsKOpskozks5q44jNgaJpZM4KkEq9
.

[som-snytt]

A sympathy comment: I hit the same issue looking at https://issues.scala-lang.org/browse/SI-10007 and you scratch your head looking at thread dumps.

[adriaanm]

Viktor, it's a consequence of the new lambda encoding, which is also how Java does it. I don't know how we could change this and still use invokedynamic. There's a SIP for less deadlock-prone object/lazy val initialization that will likely get into 2.13. /cc @retronym

[adriaanm]

To make this more concrete:

object O { 
  def f = (x: Int) => x
  f(1)
}

compiles to:

public final class O {
  public static Function1<Object, Object> f() {
    return O$.MODULE$.f();
  }
}

public final class O$ {
  public static O$ MODULE$;
  public static { new O$();  }
  private O$() {
    MODULE$ = this;
    this.f().apply$mcII$sp(1);
  }

  public scala.Function1<Object, Object> f() { return x -> x;  }
}

[viktorklang]

I probably over-interpreted it.
Is the problem only manifesting because the logic is executed as the
object initializer?

(I am a contributor to the improved lazy init so I'd of course want it as
soon as possible. 😊)

Cheers,
√

On Oct 30, 2016 2:47 AM, "Adriaan Moors" notifications@github.com wrote:

Viktor, it's a consequence of the new lambda encoding, which is also how
Java does it. I don't know how we could change this and still use
invokedynamic. There's a SIP for less deadlock-prone object/lazy val
initialization that will likely get into 2.13. /cc @retronym
https://github.com/retronym

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
#290 (comment),
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAAqd9b0HUHxvh2bCVoaINxaIzzb0D8cks5q4-kPgaJpZM4KkEq9
.

[larsrh]

So, to summarize: It's not a problem in ScalaCheck per se, but it is exhibited by the fact that the ScalaCheck runner

• uses objects instead of instantiating classes, and
• if a property is constructed from a plain Boolean, this is not done lazily

Is that assessment correct?

[non]

The simplest change which would fix this issue (for the end-user, in this case @larsrh) is something like this:

-  property("stack safety") = {
+  property("stack safety") = P {
     import ExecutionContext.Implicits.global
     fromFuture(Future(1)).run == 1
   }
 }
+
+object P {
+  def apply(body: => Boolean): Prop =
+    Prop(_ => Prop.Result(if (body) Prop.True else Prop.False))
+}

@larsrh @rickynils Do you think ScalaCheck should support something like this? If P was instead some method on Prop it would make fixing these issues relatively straightforward (albeit still annoying).