Thread dump blocked AND locked

Question

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.

Answer 1

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.

Answer 2

A lock is acquired on each Logger while iterating over its appenders to prevent concurrent changes to the appender collection. If one thread is blocked in an appender (for example, writing events over a network connection) other threads logging to that Logger instance must wait for the lock. An AsyncAppender can be used to buffer events and minimize contention, but at the risk of losing events in the buffer.

The strange thing is not that you see "locked" instead of "waiting to lock", but that you don't see "waiting to lock" in addition to "locked". That is, it appears that the thread in question is the one that won the race to acquire the log on a given category, and is now waiting to acquire an additional lock on some other object. The mystery, then, is why doesn't the dump identify the other object?

I think your assumption that its the Logger on which it already holds the lock is incorrect.

Still wondering what is the exact version you are using?