一個與Log4j相關的死鎖（轉）

 這個死鎖的原因：一個動作需要兩個臨界對象。
靜態同步方法，就是一個臨界對象。
這種場景，靜態同步方法每次只能有一個線程持有。
如果存在另一個臨界對象，靜態同步方法中也需要獲取這個臨界對象。即一個動作需要兩個臨界對象。

We are experiencing deadlocks on our server.

We have tested with log4j version 1.2.8 up to and including 1.2.15

We have identified that cause to be a log statement inside a 
synchronized block,
which is called from different threads.

We have attached to very simplified classes, to reproduce the deadlock. 
Our framework is a lot more complex, where log4j can be called 
indirectly with reflection, not neccessarily by us, but from third party 
libraries etc.

The deadlock can be reproduced always.

Is our usage (or library usage) of log4j faulty, or is it a bug?

import org.apache.log4j.Logger;

public class FindDeadLock {

    public static void main(String[] args) {
        new Thread(new Runnable() {
            public void run() {
                Logger.getLogger(getClass()).info(new FindDeadLock());
            }
        }).start();
        DeadLockingObject.getInstance();//lineNO:13
    }

    public String toString() {
        /* now we are inside log4j, try to create a DeadLockingObject */
        DeadLockingObject.getInstance();
        return "Created DeadlockObject, returning string";
    }
}

import org.apache.log4j.Logger;

public final class DeadLockingObject {
    private static final Logger LOG = Logger.getLogger(DeadLockingObject.class
            .getName());
    private static DeadLockingObject singleton = new DeadLockingObject();

    private DeadLockingObject() {
    }

    public synchronized static DeadLockingObject getInstance() {
        try {
            // to make the deadlock occur
            Thread.sleep(100);
        } catch (InterruptedException e) {
            LOG.error(e);
        }
        LOG.info("Returning nice singleton");//lineNO:20
        return singleton;
    }
}

Here is our log4j configuration: 

# Set root logger level to DEBUG and its only appender to A1. 
log4j.rootLogger=INFO, A1 

# A1 is set to be a ConsoleAppender. 
log4j.appender.A1=org.apache.log4j.ConsoleAppender 

# A1 uses PatternLayout. 
log4j.appender.A1.layout=org.apache.log4j.PatternLayout 
log4j.appender.A1.layout.ConversionPattern=%-4r [%t] %-5p %c %x - %m%n 

Analyse:

"main" - Thread t@1
   java.lang.Thread.State: BLOCKED
    at org.apache.log4j.Category.callAppenders(Category.java:205)
    - waiting to lock <341960> (a org.apache.log4j.spi.RootLogger) owned by "Thread-0" t@8
    at org.apache.log4j.Category.forcedLog(Category.java:391)
    at org.apache.log4j.Category.info(Category.java:666)
    at loggerlock.DeadLockingObject.getInstance(DeadLockingObject.java:20)
    - locked <105738> (a java.lang.Class)
    at loggerlock.FindDeadLock.main(FindDeadLock.java:13)

   Locked ownable synchronizers:
    - None

main線程:

(1)DeadLockingObject.getInstance();//獲取DeadLockingObject class級別的鎖
(2)LOG.info("Returning nice singleton");//打印日志需要依次獲取class org.apache.log4j.spi.RootLogger、org.apache.log4j.ConsoleAppender的鎖

"Thread-0" - Thread t@8
   java.lang.Thread.State: BLOCKED
    at loggerlock.DeadLockingObject.getInstance(DeadLockingObject.java:16)
    - waiting to lock <105738> (a java.lang.Class) owned by "main" t@1
    at loggerlock.FindDeadLock.toString(FindDeadLock.java:18)
    at org.apache.log4j.or.DefaultRenderer.doRender(DefaultRenderer.java:37)
    at org.apache.log4j.or.RendererMap.findAndRender(RendererMap.java:80)
    at org.apache.log4j.spi.LoggingEvent.getRenderedMessage(LoggingEvent.java:368)
    at org.apache.log4j.helpers.PatternParser$BasicPatternConverter.convert(PatternParser.java:402)
    at org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:65)
    at org.apache.log4j.PatternLayout.format(PatternLayout.java:506)
    at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:310)
    at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
    at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
    - locked <81aa7a> (a org.apache.log4j.ConsoleAppender)
    at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
    at org.apache.log4j.Category.callAppenders(Category.java:206)
    - locked <341960> (a org.apache.log4j.spi.RootLogger)
    at org.apache.log4j.Category.forcedLog(Category.java:391)
    at org.apache.log4j.Category.info(Category.java:666)
    at loggerlock.FindDeadLock$1.run(FindDeadLock.java:10)
    at java.lang.Thread.run(Unknown Source)

   Locked ownable synchronizers:
    - None

 

Thread-0線程：
(1)Logger.getLogger(getClass()).info(。。。//
//獲取Class org.apache.log4j.spi.RootLogger的鎖
//獲取Class org.apache.log4j.ConsoleAppender的鎖
(3)new FindDeadLock()的toString方法中

DeadLockingObject.getInstance();//需要獲取Class DeadLockingObject鎖
http://apache-logging.6191.n7.nabble.com/Log4j-1-2-x-deadlock-bug-or-faulty-usage-td7658.html

Tips:
(1)線程狀態 waiting for monitor entry 表示目前線程正在等待去鎖住一個對象（其它線程可能正擁有該對象鎖）。該現象會發生在當多線程同時去執行同步代碼塊或方法時。注意鎖是對對象而言的，而不是單個的方法，也就是說當一個線程去執行某個對象的同步方法時，它須先鎖住那個對象。
(2)

要找出所有Thread棧信息，並且分類排序，比如：

因為log4j等待Logger的而阻塞的有多少條線程，這種：
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.log4j.Category.callAppenders(Category.java:204)
- waiting to lock <0x00002aab2f555948> (a org.apache.log4j.spi.RootLogger)

因為JDBC操作等待數據庫返回的有多少條線程，這種：
ava.lang.Thread.State: BLOCKED (on object monitor)
at oracle.jdbc.driver.T4CMAREngine.unmarshalDALC(T4CMAREngine.java:2347)
at oracle.jdbc.driver.T4C8TTIuds.unmarshal(T4C8TTIuds.java:134)
at oracle.jdbc.driver.T4CTTIdcb.receiveCommon(T4CTTIdcb.java:155)

然后根據數量規模排序，來判斷瓶頸可能發生的位置。
http://bbs.csdn.net/topics/390033107?page=1#post-398824236