search

olivergondza / dumpling

DSL based threaddump analyzer
https://olivergondza.github.io/dumpling/
MIT License
15 stars 3 forks source link

Multiple threads own the same monitor on Oracle JDK 8 via JVM factory #81

Open olivergondza opened 7 years ago

olivergondza commented 7 years ago 
"Handling POST /hudson/.../ajaxExecutors from 10.40.5.121 : RequestHandlerThread[#25028] View/ajaxExecutors.jelly" #6538558 daemon prio=5
   java.lang.Thread.State: RUNNABLE
  at java.lang.Object.hashCode(Native Method)
  at java.util.WeakHashMap.hash(WeakHashMap.java:298)
  at java.util.WeakHashMap.get(WeakHashMap.java:396)
  at org.apache.commons.beanutils.ContextClassLoaderLocal.get(ContextClassLoaderLocal.java:150)
  - locked <0x00000000631d228c> (a org.apache.commons.beanutils.WrapDynaClass$1)
  at org.apache.commons.beanutils.WrapDynaClass.getDynaClassesMap(WrapDynaClass.java:136)
  at org.apache.commons.beanutils.WrapDynaClass.createDynaClass(WrapDynaClass.java:359)
  at org.apache.commons.beanutils.WrapDynaBean.getDynaClass(WrapDynaBean.java:216)
  at org.apache.commons.beanutils.WrapDynaBean.<init>(WrapDynaBean.java:64)
  at org.apache.commons.beanutils.ConvertingWrapDynaBean.<init>(ConvertingWrapDynaBean.java:48)
  at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:246)
     ...

   Locked ownable synchronizers:
  - <0x00000000252fb802> (a java.util.concurrent.ThreadPoolExecutor$Worker)
"Handling POST /hudson/.../ajaxExecutors from 10.40.5.141 : RequestHandlerThread[#25017] View/ajaxExecutors.jelly" #6538441 daemon prio=5
   java.lang.Thread.State: RUNNABLE
  at org.apache.commons.beanutils.ContextClassLoaderLocal.get(ContextClassLoaderLocal.java:144)
  - locked <0x00000000631d228c> (a org.apache.commons.beanutils.WrapDynaClass$1)
  at org.apache.commons.beanutils.WrapDynaClass.getDynaClassesMap(WrapDynaClass.java:136)
  at org.apache.commons.beanutils.WrapDynaClass.createDynaClass(WrapDynaClass.java:359)
  at org.apache.commons.beanutils.WrapDynaBean.getDynaClass(WrapDynaBean.java:216)
  at org.apache.commons.beanutils.WrapDynaBean.<init>(WrapDynaBean.java:64)
  at org.apache.commons.beanutils.ConvertingWrapDynaBean.<init>(ConvertingWrapDynaBean.java:48)
  at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:246)
     ...

   Locked ownable synchronizers:
  - <0x000000001eda3583> (a java.util.concurrent.ThreadPoolExecutor$Worker)
olivergondza commented 7 years ago 
"Computer.threadPoolForRemoting [#717237]" #6830404 daemon prio=5
   java.lang.Thread.State: RUNNABLE
    at sun.misc.Unsafe.unpark(Native Method)
    at java.util.concurrent.locks.LockSupport.unpark(LockSupport.java:141)
    at java.util.concurrent.SynchronousQueue$TransferStack$SNode.tryMatch(SynchronousQueue.java:265)
    at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:383)
    at java.util.concurrent.SynchronousQueue.offer(SynchronousQueue.java:913)
    at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1361)
    at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:134)
    at com.google.common.util.concurrent.ForwardingExecutorService.submit(ForwardingExecutorService.java:105)
    at jenkins.util.InterceptingExecutorService.submit(InterceptingExecutorService.java:39)
    at hudson.remoting.DelegatingExecutorService.submit(DelegatingExecutorService.java:42)
    at hudson.remoting.InterceptingExecutorService.submit(InterceptingExecutorService.java:42)
    at hudson.remoting.InterceptingExecutorService.submit(InterceptingExecutorService.java:37)
    at hudson.remoting.SingleLaneExecutorService$1.run(SingleLaneExecutorService.java:120)
    - locked <0x000000006734f65a> (a hudson.remoting.SingleLaneExecutorService)
    at hudson.remoting.InterceptingExecutorService$1.call(InterceptingExecutorService.java:68)
    at org.jenkinsci.remoting.CallableDecorator.call(CallableDecorator.java:18)
    at hudson.remoting.CallableDecoratorList$1.call(CallableDecoratorList.java:21)
    at jenkins.util.ContextResettingExecutorService$2.call(ContextResettingExecutorService.java:46)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    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)

   Locked ownable synchronizers:
    - <0x0000000004a35aec> (a java.util.concurrent.ThreadPoolExecutor$Worker)
"Channel reader thread: soavmg11-rhel6-x86" #6369546 prio=5
   java.lang.Thread.State: RUNNABLE
    at hudson.remoting.SingleLaneExecutorService.execute(SingleLaneExecutorService.java:99)
    - locked <0x000000006734f65a> (a hudson.remoting.SingleLaneExecutorService)
    at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:112)
    at hudson.remoting.PipeWriter.submit(PipeWriter.java:152)
    at hudson.remoting.ProxyOutputStream$Chunk.execute(ProxyOutputStream.java:243)
    at hudson.remoting.Channel$1.handle(Channel.java:498)
    at hudson.remoting.SynchronousCommandTransport$ReaderThread.run(SynchronousCommandTransport.java:60)
olivergondza commented 7 years ago 
"Thread-164798" #7400334 daemon prio=5
   java.lang.Thread.State: RUNNABLE
    at com.trilead.ssh2.channel.FifoBuffer.write(FifoBuffer.java:154)
    - locked <0x00000000546b5a80> (a com.trilead.ssh2.channel.Channel)
    at com.trilead.ssh2.channel.Channel$Output.write(Channel.java:93)
    at com.trilead.ssh2.channel.ChannelManager.msgChannelData(ChannelManager.java:981)
    - locked <0x00000000546b5a80> (a com.trilead.ssh2.channel.Channel)
    at com.trilead.ssh2.channel.ChannelManager.handleMessage(ChannelManager.java:1460)
    at com.trilead.ssh2.transport.TransportManager.receiveLoop(TransportManager.java:796)
    at com.trilead.ssh2.transport.TransportManager$1.run(TransportManager.java:489)
    at java.lang.Thread.run(Thread.java:745)
"Computer.threadPoolForRemoting [#788368] : IO ID=162653 : seq#=162652" #7414119 daemon prio=5
   java.lang.Thread.State: RUNNABLE
    at com.trilead.ssh2.channel.ChannelManager.sendData(ChannelManager.java:368)
    - locked <0x00000000546b5a80> (a com.trilead.ssh2.channel.Channel)
    at com.trilead.ssh2.channel.ChannelOutputStream.write(ChannelOutputStream.java:63)
    at hudson.remoting.ChunkedOutputStream.sendFrame(ChunkedOutputStream.java:94)
    at hudson.remoting.ChunkedOutputStream.sendBreak(ChunkedOutputStream.java:66)
    at hudson.remoting.ChunkedCommandTransport.writeBlock(ChunkedCommandTransport.java:46)
    at hudson.remoting.AbstractSynchronousByteArrayCommandTransport.write(AbstractSynchronousByteArrayCommandTransport.java:45)
    at hudson.remoting.Channel.send(Channel.java:579)
    - locked <0x000000002d540f12> (a hudson.remoting.Channel)
    at hudson.remoting.ProxyOutputStream$Chunk$1.run(ProxyOutputStream.java:261)
    at hudson.remoting.PipeWriter$1.run(PipeWriter.java:158)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at hudson.remoting.SingleLaneExecutorService$1.run(SingleLaneExecutorService.java:112)
    at hudson.remoting.InterceptingExecutorService$1.call(InterceptingExecutorService.java:68)
    at org.jenkinsci.remoting.CallableDecorator.call(CallableDecorator.java:18)
    at hudson.remoting.CallableDecoratorList$1.call(CallableDecoratorList.java:21)
    at jenkins.util.ContextResettingExecutorService$2.call(ContextResettingExecutorService.java:46)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    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)

   Locked ownable synchronizers:
    - <0x000000003864e926> (a java.util.concurrent.ThreadPoolExecutor$Worker)
olivergondza commented 7 years ago

There seem to be a pattern here - one thread has acquired the monitor somewhere deep in stacktrace while the other have it on current stackframe. While I have no idea why would it be so, retry might help.

jtnord commented 1 year ago

I may be wrong but jstack like Thread.getAllStackTraces does not give you a consistend single time entry of the entire status.

Rather first it gets a list of threads then gets a snapshot of the the stack of each of those threads one by one https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/lang/Thread.html#getAllStackTraces()

The threads may be executing while this method is called. The stack trace of each thread only represents a snapshot and each stack trace may be obtained at different time. A zero-length array will be returned in the map value if the virtual machine has no stack trace information about a thread.

so that could explain the above - one thread that had the lock now no longer does, and so a different thread obtained it by the time the stack for that thread was obtained.

olivergondza commented 1 year ago

@jtnord, that is true. Dumpling have a long history of massaging the thread snapshot (or a runtime as we call it). It is shocking how many inconsistencies there can be, but for now, we were somewhat successful in deriving a potent runtime off of it anyway. It is somewhat surprising we have seen those a lot more often in jstack produced threaddumps.