2

My Web application, which runs in Apache Tomcat/8.0.21, with JVM 1.8.0_45-b15 and Windows Server 2012 on a 16-core (32- with HT) Dual-Xeon NUMA machine, can get stuck, in some very unfortunate circumstances, when the actions described in the title occur at the same time in two different threads.

The thread doing the first action (getStackTrace()) is trying to perform some diagnostic to detect which part of the system is slowing things down and gets stuck while calling Thread.dumpThreads. The other thread is doing some operation, which includes under-the-hood lambda definition on part of the JVM.

In particular, I have the following stack trace (obtained with jstack -F <pid>):

Attaching to process ID 6568, please wait... 
Debugger attached successfully. 
Server compiler detected. 
JVM version is 25.45-b02 

Deadlock Detection:

No deadlocks found. (... well, that's not the kind of deadlock you were searching for, dear JVM, but something bad is happening altogether :( )

Thread 155: (state = BLOCKED)
 - sun.misc.Unsafe.defineAnonymousClass(java.lang.Class, byte[], java.lang.Object[]) @bci=0 (Compiled frame; information may be imprecise)
 - java.lang.invoke.InvokerBytecodeGenerator.loadAndInitializeInvokerClass(byte[], java.lang.Object[]) @bci=8 (Compiled frame)
 - java.lang.invoke.InvokerBytecodeGenerator.loadMethod(byte[]) @bci=6 (Compiled frame)
 - java.lang.invoke.InvokerBytecodeGenerator.generateCustomizedCode(java.lang.invoke.LambdaForm, java.lang.invoke.MethodType) @bci=17 (Compiled frame)
 - java.lang.invoke.LambdaForm.compileToBytecode() @bci=65 (Compiled frame)
 - java.lang.invoke.DirectMethodHandle.makePreparedLambdaForm(java.lang.invoke.MethodType, int) @bci=638 (Interpreted frame)
 - java.lang.invoke.DirectMethodHandle.preparedLambdaForm(java.lang.invoke.MethodType, int) @bci=17 (Compiled frame)
 - java.lang.invoke.DirectMethodHandle.preparedLambdaForm(java.lang.invoke.MemberName) @bci=163 (Compiled frame)
 - java.lang.invoke.DirectMethodHandle.make(byte, java.lang.Class, java.lang.invoke.MemberName) @bci=94 (Compiled frame)
 - java.lang.invoke.MethodHandles$Lookup.getDirectMethodCommon(byte, java.lang.Class, java.lang.invoke.MemberName, boolean, boolean, java.lang.Class) @bci=201 (Compiled frame)
 - java.lang.invoke.MethodHandles$Lookup.getDirectMethodNoSecurityManager(byte, java.lang.Class, java.lang.invoke.MemberName, java.lang.Class) @bci=8 (Compiled frame)
 - java.lang.invoke.MethodHandles$Lookup.getDirectMethodForConstant(byte, java.lang.Class, java.lang.invoke.MemberName) @bci=30 (Compiled frame)
 - java.lang.invoke.MethodHandles$Lookup.linkMethodHandleConstant(byte, java.lang.Class, java.lang.String, java.lang.Object) @bci=115 (Compiled frame)
 - java.lang.invoke.MethodHandleNatives.linkMethodHandleConstant(java.lang.Class, int, java.lang.Class, java.lang.String, java.lang.Object) @bci=38 (Compiled frame)
 - c.e.s.w.t.si.a.DDVP.lambda$1(com.vaadin.data.Container, com.vaadin.ui.HorizontalLayout, com.vaadin.ui.Label, com.vaadin.ui.Label, java.lang.String, java.lang.String, java.util.Map) @bci=48, line=104 (Interpreted frame)
 - c.e.s.w.t.si.a.DDVP$$Lambda$637.updateUIWith(java.lang.Object) @bci=32 (Interpreted frame)
 - c.e.s.w.d.DU$VoidUIUpdaterFromUIUpdater.updateUI() @bci=8, line=321 (Compiled frame)
 - c.e.s.w.d.DU$CompletionSignallingVoidUIUpdater.updateUI() @bci=4, line=125 (Compiled frame)
 - c.e.s.w.d.CUQ$1.sweepWhileNotTimedOut() @bci=59, line=218 (Compiled frame)
 - c.e.s.w.d.CUQ$QueueExhauster.run() @bci=247, line=122 (Compiled frame)
 - c.e.s.w.d.CUQ$DequeuerStartFailed.run() @bci=40, line=60 (Compiled frame)
 - c.e.s.w.s.ew.CC.lambda$4(java.lang.Runnable) @bci=13, line=66 (Compiled frame)
 - c.e.s.w.s.ew.CC$$Lambda$59.run() @bci=8 (Compiled frame)
 - java.util.concurrent.ThreadPoolExecutor.runWorker(java.util.concurrent.ThreadPoolExecutor$Worker) @bci=95 (Compiled frame)
 - java.util.concurrent.ThreadPoolExecutor$Worker.run() @bci=5 (Interpreted frame)
 - java.lang.Thread.run() @bci=11 (Compiled frame)

Thread 108: (state = BLOCKED) [The tricky one...]
 - java.lang.Thread.dumpThreads(java.lang.Thread[]) @bci=0 (Interpreted frame)
 - java.lang.Thread.getStackTrace() @bci=41 (Compiled frame)
 - c.e.s.w.SWA$$Lambda$98.getStackTrace() @bci=4 (Interpreted frame)
 - c.e.s.w.SWA.describeHoggingCode(c.e.s.w.s.RequestTimeTracker$StackTraceProvider, boolean) @bci=1, line=401 (Interpreted frame)
 - c.e.s.w.SWA.describeHoggingCode(c.e.s.w.s.RequestTimeTracker$StackTraceProvider, boolean, java.lang.Thread) @bci=6, line=396 (Interpreted frame)
 - c.e.s.w.SWA.lambda$10(java.lang.Thread, java.lang.String) @bci=8, line=890 (Interpreted frame)
 - c.e.s.w.SWA$$Lambda$62.run() @bci=12 (Interpreted frame)
 - c.e.s.w.s.ew.CC.lambda$4(java.lang.Runnable) @bci=13, line=66 (Compiled frame)
 - c.e.s.w.s.ew.CC$$Lambda$59.run() @bci=8 (Compiled frame)
 - c.e.s.w.s.IS.lambda$4(java.util.concurrent.atomic.AtomicBoolean, java.lang.Runnable) @bci=8, line=327 (Compiled frame)
 - c.e.s.w.s.IS$$Lambda$60.run() @bci=8 (Compiled frame)
 - java.util.concurrent.Executors$RunnableAdapter.call() @bci=4 (Compiled frame)
 - java.util.concurrent.FutureTask.run() @bci=42 (Compiled frame)
 - java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask) @bci=1 (Compiled frame)
 - java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run() @bci=30 (Compiled frame)
 - java.util.concurrent.ThreadPoolExecutor.runWorker(java.util.concurrent.ThreadPoolExecutor$Worker) @bci=95 (Compiled frame)
 - java.util.concurrent.ThreadPoolExecutor$Worker.run() @bci=5 (Interpreted frame)
 - java.lang.Thread.run() @bci=11 (Interpreted frame)

From my point of view, this issue could be related to Unsafe.defineAnonymousClass not being able to cope with an ongoing call to java.lang.Thread.dumpThreads (which, in turn, is needed to implement java.lang.Thread.getStackTrace, inside JVM). The key point is that, due final or package modifiers, I'm not able to extend any of the core classes involved in this process (such as Lookup, MethodHandleNatives, etc.) in order to introduce a lock which would be blocking tricky Unsafe calls while a call to java.lang.Thread.dumpThreads is still ongoing. Also, I suspect that introducing such lock could also slow things down quite a bit, since, well, lambdas are everywhere.

Has anyone encountered a similar problem? Could you help solving it?

Thank you!

Of course, in the stacktrace were also threads like these, which I omitted since I think they are not relevant to this case.

Thread 154: (state = BLOCKED) [Many of these....]
 - sun.misc.Unsafe.park(boolean, long) @bci=0 (Compiled frame; information may be imprecise)
 - java.util.concurrent.locks.LockSupport.parkNanos(java.lang.Object, long) @bci=20 (Compiled frame)
 - java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(long) @bci=78 (Compiled frame)
 - org.eclipse.jetty.util.BlockingArrayQueue.poll(long, java.util.concurrent.TimeUnit) @bci=57, line=389 (Compiled frame)
 - org.eclipse.jetty.util.thread.QueuedThreadPool.idleJobPoll() @bci=12, line=516 (Compiled frame)
 - org.eclipse.jetty.util.thread.QueuedThreadPool.access$700(org.eclipse.jetty.util.thread.QueuedThreadPool) @bci=1, line=47 (Compiled frame)
 - org.eclipse.jetty.util.thread.QueuedThreadPool$3.run() @bci=300, line=575 (Compiled frame)
 - java.lang.Thread.run() @bci=11 (Compiled frame)


Thread 153: (state = BLOCKED) [and of these...]
 - sun.misc.Unsafe.park(boolean, long) @bci=0 (Compiled frame; information may be imprecise)
 - java.util.concurrent.ForkJoinPool.awaitWork(java.util.concurrent.ForkJoinPool$WorkQueue, int) @bci=354 (Compiled frame)
 - java.util.concurrent.ForkJoinPool.runWorker(java.util.concurrent.ForkJoinPool$WorkQueue) @bci=44 (Interpreted frame)
 - java.util.concurrent.ForkJoinWorkerThread.run() @bci=24 (Interpreted frame)


Thread 141: (state = BLOCKED) [and of these...]
 - sun.misc.Unsafe.park(boolean, long) @bci=0 (Compiled frame; information may be imprecise)
 - java.util.concurrent.locks.LockSupport.park(java.lang.Object) @bci=14 (Compiled frame)
 - java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await() @bci=42 (Compiled frame)
 - java.util.concurrent.LinkedBlockingQueue.take() @bci=29 (Compiled frame)
 - org.apache.tomcat.util.threads.TaskQueue.take() @bci=36, line=103 (Compiled frame)
 - org.apache.tomcat.util.threads.TaskQueue.take() @bci=1, line=31 (Compiled frame)
 - java.util.concurrent.ThreadPoolExecutor.getTask() @bci=149 (Compiled frame)
 - java.util.concurrent.ThreadPoolExecutor.runWorker(java.util.concurrent.ThreadPoolExecutor$Worker) @bci=26 (Interpreted frame)
 - java.util.concurrent.ThreadPoolExecutor$Worker.run() @bci=5 (Interpreted frame)
 - org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run() @bci=4, line=61 (Interpreted frame)
 - java.lang.Thread.run() @bci=11 (Interpreted frame)
logtwo
  • 502
  • 5
  • 12
  • Please show the relevant code as well. – Jagannath May 20 '15 at 12:09
  • 1
    That’s strange as `jstack` proves at the same time that dumping all stack traces is possible. – Holger May 20 '15 at 12:40
  • @Jagannath, which code? Alas, I can't post product's code, since it is customer's property. However, I can tell you that first thread is owning a intrinsic lock, but no other thread is trying to lock that. In fact, apart from the two blocked thread and Tomcat's worker threads, it seems that there's no other activity. Going back to code, which kind of bad smell are you trying to find out in it? If you can tell me your idea, I can check if that's the case. – logtwo May 20 '15 at 12:43
  • @Holger, in fact I was forced to use `-F` parameter to dump the stack; without `-F`, `jstack` didn't work. Also, no other tools (such as JConsole, JVisualVM, JMC, ...) were able to attach to the JVM, which thus resulted in being stuck. – logtwo May 20 '15 at 12:46
  • @Holger, now I see your point. I suspect that dumping of all threads' stacktraces which is called inside `getStackTrace()` follows a different path, other than the one is called inside `jstack`. I will look into the details of the latter, trying to find out the differences. Thank you for the hint! – logtwo May 20 '15 at 13:00
  • @Holger, I think that the relevant piece of information about how `jstack` (with `-F` option) works is in [this comment](http://stackoverflow.com/a/12179211/942036). You can also find source code [here](http://grepcode.com/file/repository.grepcode.com/java/root/jdk/openjdk/8u40-b25/sun/tools/jstack/JStack.java#JStack). If I interpreted correctly, _forced jstack_ used Debugger Interface (with the help of Windows, in fact the process is suspended while stack is being extracted), so it should be not surprising that dump succeeds, even if the process is stuck. – logtwo May 20 '15 at 14:33

1 Answers1

2

Finally I managed to solve this nasty issue. It appears that JVM can get stuck with traces like the ones if posted (involving at least sun.misc.Unsafe.defineAnonymousClass) if the option -XX:-ClassUnloading is passed on to the JVM executable (as was the case for the JVM I was trying to cure). For some reason this can stimulate this deadlock-style bug in Java system libraries, which appears to be random (as all deadlock bugs) and getting more and more likely as JVM process "ages". Again, this is nothing new for deadlock bugs: the more "gears" (say, classes which should had been unloaded but weren't due to that option) you put into the machine, the more likely is that two or more of them crank.

As a result, removing the option -XX:-ClassUnloading makes this problem completely disappear.

The bottom line is: never use -XX:-ClassUnloading in production systems (or let anyone put such option in JVM process starting scripts), not even in Java8, which shouldn't be limited by PermGen, yet it still can suffer badly due to problem in sun.misc.Unsafe.defineAnonymousClass .

logtwo
  • 502
  • 5
  • 12