Java – Thread dump blocked AND locked

garbage-collectionjavamultithreadingsynchronizedthread-dump

This is similar to Java thread dump: BLOCKED thread without "waiting to lock …".

Basically, I am seeing a BLOCKED thread but it has the lock it is waiting for:

"pool-1-thread-60" prio=10 tid=0x00007fbf10017000 nid=0x210 waiting for monitor entry [0x00007fbed64e3000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at org.apache.log4j.Category.callAppenders(Category.java:204)
        - locked <0x0000000742444ad0> (a org.apache.log4j.Logger)
        at org.apache.log4j.Category.forcedLog(Category.java:391)
        at org.apache.log4j.Category.info(Category.java:666)
        ...

I would expect to see - waiting to lock <0x0000000742444ad0>... instead of - locked.... The other question suggests that garbage collection is the cause but if that were the case wouldn't all threads be BLOCKED? There are other threads which are RUNNABLE. Also, how could I prove that was the case? Why would this be the observed behavior? I don't want to go blindly assuming it is the garbage collector only to find out days later it was something else.

==Auxiliary info==

Although I don't think it relevant to the issue at hand, this is the section of code that the above dump came from.

for(Category c = this; c != null; c=c.parent) {
  // Protected against simultaneous call to addAppender, removeAppender,...
  synchronized(c) { //line 204
if(c.aai != null) {
  writes += c.aai.appendLoopOnAppenders(event);
}
if(!c.additive) {
  break;
}
  }
}

Clearly there is a lock that needs to be obtained on that line. HOWEVER, when a thread is truly blocked on this monitor the output in the thread dump appears like (this comes from the same dump):

"pool-1-thread-44" prio=10 tid=0x00007fbef0051000 nid=0x200 waiting for monitor\
 entry [0x00007fbed74f3000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at org.apache.log4j.Category.callAppenders(Category.java:204)
        - waiting to lock <0x0000000742444ad0> (a org.apache.log4j.Logger)
        at org.apache.log4j.Category.forcedLog(Category.java:391)
        at org.apache.log4j.Category.info(Category.java:666)
        ...

The section of the dump I am interested in looks different ("locked" instead of "waiting to lock"). I have debugged many deadlocks and looked at lots of thread dumps. What I always see is the "waiting to lock". I have never seen a thread that is "locked" but still "waiting for monitor entry" and I want to know what that means.

Best Answer

This is a known cosmetic bug in Oracle's HotSpot JVM. As you say, in your stack trace where you see - locked <0x00007f3e9a0b3830> it should actually say - waiting to lock <0x00007f3e9a0b3830> since the thread has not yet acquired the relevant lock.

See this bug for more details.