Transient deadlock while running Puma tests

[eregon]

Noticed by @chrisseaton.
Full stracktraces at https://gist.github.com/chrisseaton/a7d96d389cd14a536665b4560c8447b0

[eregon]

With a small script to narrow to the relevant output we see:
https://gist.github.com/eregon/697943c555270b1d26e0efc1e9d2d711

com.oracle.svm.core.monitor.MultiThreadedMonitorSupport.slowPathMonitorEnter(MultiThreadedMonitorSupport.java:138)
org.truffleruby.core.FinalizationService.removeFinalizers(FinalizationService.java:105)
org.truffleruby.extra.ffi.Pointer.disableAutorelease(Pointer.java:296)
org.truffleruby.extra.ffi.Pointer.free(Pointer.java:223)
org.truffleruby.extra.ffi.PointerNodes$PointerFreeNode.free(PointerNodes.java:199)

com.oracle.svm.core.monitor.MultiThreadedMonitorSupport.monitorEnter(MultiThreadedMonitorSupport.java:166)
com.oracle.svm.core.monitor.MultiThreadedMonitorSupport.slowPathMonitorEnter(MultiThreadedMonitorSupport.java:138)
org.truffleruby.core.FinalizationService.addFinalizer(FinalizationService.java:54)
org.truffleruby.extra.ffi.Pointer.enableAutorelease(Pointer.java:266)
org.truffleruby.extra.ffi.PointerNodes$PointerSetAutoreleaseNode.enableAutorelease(PointerNodes.java:171)

com.oracle.svm.core.monitor.MultiThreadedMonitorSupport.slowPathMonitorEnter(MultiThreadedMonitorSupport.java:138)
org.truffleruby.core.FinalizationService.addFinalizer(FinalizationService.java:54)
org.truffleruby.extra.ffi.Pointer.enableAutorelease(Pointer.java:266)
org.truffleruby.core.rope.NativeRope.allocateNativePointer(NativeRope.java:49)
org.truffleruby.core.rope.NativeRope.<init>(NativeRope.java:35)
org.truffleruby.cext.CExtNodes$StringToNativeNode.toNative(CExtNodes.java:1022)
org.truffleruby.cext.CExtNodesFactory$StringToNativeNodeGen.executeToNative(CExtNodesFactory.java:4148)
org.truffleruby.cext.CExtNodes$StringPointerToNativeNode.toNative(CExtNodes.java:1037)

com.oracle.svm.core.monitor.MultiThreadedMonitorSupport.slowPathMonitorEnter(MultiThreadedMonitorSupport.java:138)
org.truffleruby.core.FinalizationService.addFinalizer(FinalizationService.java:54)
org.truffleruby.extra.ffi.Pointer.enableAutorelease(Pointer.java:266)
org.truffleruby.core.rope.NativeRope.copyNativePointer(NativeRope.java:57)
org.truffleruby.core.rope.NativeRope.makeCopy(NativeRope.java:82)
org.truffleruby.core.string.StringNodes$InitializeCopyNode.initializeCopyFromNative(StringNodes.java:1455)

So the 4 threads are trying to acquire the monitor of FinalizationService.
All of them also have acquired a monitor on some Pointer instance, but at least some on different instances.

So probably one of the threads which reached the safepoint is still holding the FinalizationService monitor.
It could be the reference processor thread, but the only place it seems to hold the FinalizationService monitor is FinalizationService#processReferenceInternal and it doesn't check for safepoints during that time.
I don't see other places that have the FinalizationService monitor and would check safepoints or acquire another monitor inside the synchronized.

Maybe there is no finalizer thread and it's running on the current thread instead?
Then I can see that FinalizationService#addFinalizer holds the monitor and calls to referenceProcessor.processReferenceQueue() and then drainReferenceQueue() which seems problematic, so we should take that call out of the FinalizationService monitor.

That should only happen with --polyglot though.
@chrisseaton Can you make sure you don't set set --polyglot and ruby -e 'p Truffle::Interop.languages' only prints Ruby? (if it prints LLVM too, you're probably using a too old Truffle)

[eregon]

TODOs for this issue:

• Avoid holding the monitor when calling processReferenceQueue()
• Print stacktraces only once or twice on SEVERE: waited N seconds in the SafepointManager, it's too much output.
• Print stacktraces also of threads which arrive, because that might reveal which locks they hold.

[eregon]

@bjfish got a similar issue during bundle install --jobs 4, where a single thread is stuck waiting for the FinalizationService monitor:

[ruby] SEVERE: waited 5 seconds in the SafepointManager but 1 of 5 threads did not arrive - a thread is likely making a blocking native call which should use runBlockingSystemCallUntilResult() - check with jstack
Dumping stacktraces of blocked threads:
Thread[Ruby Thread id=35 from /Users/bfish/Documents/truffleruby-ws/truffleruby/mxbuild/truffleruby-native/jre/languages/ruby/lib/gems/gems/bundler-2.1.4/lib/bundler/worker.rb:88,5,main]
...
org.truffleruby.core.FinalizationService.addFinalizer(FinalizationService.java:54)
org.truffleruby.extra.ffi.Pointer.enableAutorelease(Pointer.java:266)
org.truffleruby.core.rope.NativeRope.allocateNativePointer(NativeRope.java:49)
org.truffleruby.core.rope.NativeRope.<init>(NativeRope.java:35)
org.truffleruby.cext.CExtNodes$StringToNativeNode.toNative(CExtNodes.java:1022)

[eregon]

From the bundle install we have a stacktrace for all Java threads (with -H:+AllowVMInspection + SIGQUIT) and that shows the problematic thread:

VMThread 00007f8aff683e90  STATUS_IN_SAFEPOINT

  SP 0000700000fc5860 IP 0000000105d6f0d8  [image code] com.oracle.svm.core.posix.headers.Pthread.pthread_cond_wait(Pthread.java)
  SP 0000700000fc5860 IP 0000000105d6f0d8  [image code] com.oracle.svm.core.posix.thread.PosixParkEvent.condWait(PosixJavaThreads.java:250)
  SP 0000700000fc58b0 IP 0000000105d7b373  [image code] com.oracle.svm.core.thread.JavaThreads.park(JavaThreads.java:676)
  SP 0000700000fc58e0 IP 000000010821f0a0  [image code] sun.misc.Unsafe.park(Unsafe.java:49)
  SP 0000700000fc58f0 IP 0000000106e9b5d6  [image code] java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
  SP 0000700000fc58f0 IP 0000000106e9b5d6  [image code] java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
  SP 0000700000fc5910 IP 0000000106e9818f  [image code] java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireInterruptibly(AbstractQueuedSynchronizer.java:897)
  SP 0000700000fc5960 IP 0000000106e96b24  [image code] java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(AbstractQueuedSynchronizer.java:1222)
  SP 0000700000fc5990 IP 0000000106e9d4b2  [image code] java.util.concurrent.locks.ReentrantLock.lockInterruptibly(ReentrantLock.java:335)
  SP 0000700000fc59a0 IP 0000000107a9d695  [image code] org.truffleruby.core.mutex.MutexOperations.lambda$lockInternal$0(MutexOperations.java:42)
  SP 0000700000fc59b0 IP 0000000107a9cf54  [image code] org.truffleruby.core.mutex.MutexOperations$$Lambda$bd1f2b3cf60f3dfcab84308cd0613100352a075e.block(Unknown Source)
  SP 0000700000fc59c0 IP 0000000107d5617d  [image code] org.truffleruby.core.thread.ThreadManager.runUntilResult(ThreadManager.java:525)
  SP 0000700000fc5a30 IP 0000000107a9d972  [image code] org.truffleruby.core.mutex.MutexOperations.lockInternal(MutexOperations.java:41)
  SP 0000700000fc5a70 IP 00000001075c8ce9  [image code] org.truffleruby.cext.CExtNodes$CallCWithMutexNode.callCWithMutex(CExtNodes.java:131)
  SP 0000700000fc5ac0 IP 00000001075d91bb  [image code] org.truffleruby.cext.CExtNodesFactory$CallCWithMutexNodeFactory$CallCWithMutexNodeGen.execute(CExtNodesFactory.java:240)
  SP 0000700000fc5b10 IP 0000000107fbefaa  [image code] org.truffleruby.language.control.UnlessNode.execute(UnlessNode.java:40)
  SP 0000700000fc5b40 IP 0000000107fbe613  [image code] org.truffleruby.language.control.SequenceNode.execute(SequenceNode.java:36)
  SP 0000700000fc5b70 IP 0000000108008348  [image code] org.truffleruby.language.methods.ExceptionTranslatingNode.execute(ExceptionTranslatingNode.java:33)
  SP 0000700000fc5ba0 IP 0000000107fbe613  [image code] org.truffleruby.language.control.SequenceNode.execute(SequenceNode.java:36)
  SP 0000700000fc5bd0 IP 00000001080064b0  [image code] org.truffleruby.language.methods.CatchForProcNode.execute(CatchForProcNode.java:38)
  SP 0000700000fc5c00 IP 0000000107f82a54  [image code] org.truffleruby.language.RubyRootNode.execute(RubyRootNode.java:60)
  SP 0000700000fc5c20 IP 00000001073e1960  [image code] org.graalvm.compiler.truffle.runtime.OptimizedCallTarget.executeRootNode(OptimizedCallTarget.java:484)
  SP 0000700000fc5c50 IP 00000001073e6e6b  [image code] org.graalvm.compiler.truffle.runtime.OptimizedCallTarget.profiledPERoot(OptimizedCallTarget.java:461)
  SP 0000700000fc5c80 IP 00000001073e0934  [image code] org.graalvm.compiler.truffle.runtime.OptimizedCallTarget.callBoundary(OptimizedCallTarget.java:427)
  SP 0000700000fc5ca0 IP 000000015c99d863  [Proc#call] com.oracle.svm.truffle.api.SubstrateOptimizedCallTarget.doInvoke(SubstrateOptimizedCallTarget.java:146)
  SP 0000700000fc5ca0 IP 000000015c99d863  [Proc#call] org.graalvm.compiler.truffle.runtime.OptimizedCallTarget.callIndirect(OptimizedCallTarget.java:361)
  SP 0000700000fc5ca0 IP 000000015c99d863  [Proc#call] org.graalvm.compiler.truffle.runtime.OptimizedIndirectCallNode.call(OptimizedIndirectCallNode.java:54)
  SP 0000700000fc5ca0 IP 000000015c99d863  [Proc#call] org.truffleruby.language.yield.CallBlockNode.callBlockUncached(CallBlockNode.java:65)
  SP 0000700000fc5ca0 IP 000000015c99d863  [Proc#call] org.truffleruby.language.yield.CallBlockNodeGen.executeCallBlock(CallBlockNodeGen.java:53)
  SP 0000700000fc5ca0 IP 000000015c99d863  [Proc#call] org.truffleruby.core.proc.ProcNodes$CallNode.call(ProcNodes.java:236)
  SP 0000700000fc5ca0 IP 000000015c99d863  [Proc#call] org.truffleruby.core.proc.ProcNodesFactory$CallNodeFactory$CallNodeGen.execute(ProcNodesFactory.java:657)
  SP 0000700000fc5ca0 IP 000000015c99d863  [Proc#call] org.truffleruby.language.arguments.CheckArityNode.execute(CheckArityNode.java:41)
  SP 0000700000fc5ca0 IP 000000015c99d863  [Proc#call] org.truffleruby.language.methods.ExceptionTranslatingNode.execute(ExceptionTranslatingNode.java:33)
  SP 0000700000fc5ca0 IP 000000015c99d863  [Proc#call] org.truffleruby.language.RubyRootNode.execute(RubyRootNode.java:60)
  SP 0000700000fc5ca0 IP 000000015c99d863  [Proc#call] org.graalvm.compiler.truffle.runtime.OptimizedCallTarget.executeRootNode(OptimizedCallTarget.java:484)
  SP 0000700000fc5ca0 IP 000000015c99d863  [Proc#call] org.graalvm.compiler.truffle.runtime.OptimizedCallTarget.profiledPERoot(OptimizedCallTarget.java:461)
  SP 0000700000fc5d30 IP 0000000105e01309  [image code] com.oracle.svm.truffle.api.SubstrateOptimizedCallTarget.doInvoke(SubstrateOptimizedCallTarget.java:144)
  SP 0000700000fc5d40 IP 00000001073e0a5e  [image code] org.graalvm.compiler.truffle.runtime.OptimizedCallTarget.callIndirect(OptimizedCallTarget.java:361)
  SP 0000700000fc5d70 IP 00000001073e0861  [image code] org.graalvm.compiler.truffle.runtime.OptimizedCallTarget.call(OptimizedCallTarget.java:351)
  SP 0000700000fc5da0 IP 00000001075b6b34  [image code] org.truffleruby.RubyContext.send(RubyContext.java:410)
  SP 0000700000fc5df0 IP 0000000107b40659  [image code] org.truffleruby.core.objectspace.ObjectSpaceNodes$CallableFinalizer.run(ObjectSpaceNodes.java:177)
  SP 0000700000fc5e10 IP 0000000107650f15  [image code] org.truffleruby.core.FinalizationService.processReferenceInternal(FinalizationService.java:89)
  SP 0000700000fc5e50 IP 00000001076506fc  [image code] org.truffleruby.core.FinalizationService$$Lambda$99af0ece884b7c0c2e6e72f92ac93c37f96395e3.accept(Unknown Source)
  SP 0000700000fc5e60 IP 00000001076a2b8f  [image code] org.truffleruby.core.ReferenceProcessingService.runCatchingErrors(ReferenceProcessingService.java:216)
  SP 0000700000fc5e80 IP 0000000107650c0f  [image code] org.truffleruby.core.FinalizationService.processReference(FinalizationService.java:73)
  SP 0000700000fc5ea0 IP 00000001076a1cc2  [image code] org.truffleruby.core.ReferenceProcessingService$ReferenceProcessor.drainReferenceQueue(ReferenceProcessingService.java:192)
  SP 0000700000fc5ec0 IP 00000001076a2166  [image code] org.truffleruby.core.ReferenceProcessingService$ReferenceProcessor.processReferenceQueue(ReferenceProcessingService.java:149)
  SP 0000700000fc5ed0 IP 00000001076507dc  [image code] org.truffleruby.core.FinalizationService.addFinalizer(FinalizationService.java:61)
  SP 0000700000fc5f10 IP 0000000107e0b78f  [image code] org.truffleruby.extra.ffi.Pointer.enableAutorelease(Pointer.java:266)
  SP 0000700000fc5f40 IP 000000015ce502f6  [String#initialize_copy] org.truffleruby.core.rope.NativeRope.copyNativePointer(NativeRope.java:57)
  SP 0000700000fc5f40 IP 000000015ce502f6  [String#initialize_copy] org.truffleruby.core.rope.NativeRope.makeCopy(NativeRope.java:82)
  SP 0000700000fc5f40 IP 000000015ce502f6  [String#initialize_copy] org.truffleruby.core.string.StringNodes$InitializeCopyNode.initializeCopyFromNative(StringNodes.java:1455)

As guessed above, it calls drainReferenceQueue() which is unexpected.
That's caused by getPublicLanguages() including LLVM on SVM for some reason.

[chrisseaton]

Is that stacktrace format new? That looks incredibly useful!

[eregon]

It's the stacktrace printed by SVM when using -H:+AllowVMInspection (at build time, non-default) + SIGQUIT to trigger it (like on JVM).
-H:+AllowVMInspection also reserves SIGUSR1 and SIGUSR2 (oracle/graal#744) so that would could conflict with Ruby signal handlers, so maybe we should have an extra SVM option and have SIGQUIT on by default on SVM?

[eregon]

dc8d67b is a fix/workaround to detect that the RubyLauncher is not passed --polyglot correctly on native.
Upcoming fix to address the 3 points mentioned earlier.

[eregon]

b02b82c should fix this (and provides better output if another deadlock happens with the SafepointManager).

[eregon]

@chrisseaton I enabled SIGQUIT to print the stacktraces of all threads on Native Image by default for TruffleRuby Native, and improved the output to include thread names, etc: 5bd684f
It's also now documented: https://github.com/oracle/truffleruby/blob/5bd684fc375aa5b61ac22dd5690fa4d02a20ce28/doc/user/debugging.md