一个与Log4j相关的死锁（转）

时间：2022-06-20 23:45:12

这个死锁的原因：一个动作需要两个临界对象。
静态同步方法，就是一个临界对象。
这种场景，静态同步方法每次只能有一个线程持有。
如果存在另一个临界对象，静态同步方法中也需要获取这个临界对象。即一个动作需要两个临界对象。

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

相关文章