从源码分析log4j引起的性能问题

坊间传闻，log4j对服务性能会造成不利影响，现从log4j的实现源码一探究竟。

一、从调用开始

打印日志时，接触最多的就是Logger类了。

从Logger实例的创建：

org.apache.log4j.Logger logger = Logger.getLogger("日志实例名");

到Logger实例的使用：

logger.trace("trace");
logger.info("info");
logger.error("error");

打印日志所需的一切功能都已具备，一切看起来如此简单，核心就是类Logger。

其实不然，Logger类只是提供了有限的几个方法：

logger类

其中核心方法之一：

static public Logger getLogger(String name) {
    return LogManager.getLogger(name);
}

完全依赖类LogManager的实现。然后Logger类对trace()方法做了简单的支持。其他的核心方法，全部继承自其父类，也是log4j中的核心类org.apache.log4j.Category。

而日志的打印，Category类的forceLog()方法提供了支持：

//This method creates a new logging event and logs the event
//without further checks.    
protected void forcedLog(String fqcn, Priority level, Object message, Throwable t) {
    callAppenders(new LoggingEvent(fqcn, this, level, message, t));
}

该方法依赖的callAppenders()是被认为是造成性能降低的罪魁祸首：

/**
 * Call the appenders in the hierrachy starting at
 * <code>this</code>.  If no appenders could be found, emit a
 * warning.
 *
 * <p>This method calls all the appenders inherited from the
 * hierarchy circumventing any evaluation of whether to log or not
 * to log the particular log request.
 *
 * @param event the event to log.
 */
public void callAppenders(LoggingEvent event) {
    int writes = 0;
    for (Category c = this; c != null; c = c.parent) {
        // Protected against simultaneous call to addAppender, removeAppender,...
        synchronized (c) {
            if (c.aai != null) {
                writes += c.aai.appendLoopOnAppenders(event);
            }
            if (!c.additive) {
                break;
            }
        }
    }
    if (writes == 0) {
        repository.emitNoAppenderWarning(this);
    }
}

整个日志打印的方法调用流程如下：

process

这三个方法都是类Logger的实例方法。

二、锁的竞争

源码实现中看到了同步代码块，锁竞争的确会在一定程度上造成性能降低；通常服务的业务方法或多或少都会打印日志，这导致请求处理时间增加。

从实现代码中看到，每次打印日志，都会首先获取当前对象this的内部锁(synchronized机制)，然后循环获取当前对象的parent的锁。类Category持有一个类型为Category，名为parent的属性，用以保持对父级Logger的引用。

从逻辑上讲，如果对同一个锁的竞争越激烈，对性能造成的影响约大。但是通常在业务代码中，对于每一个业务服务类，我们都会使用如下的方式：

Logger logger = Logger.getLogger(CurrentServiceClassName.class);

来获取日志实例。由于日志实例不同，那么在callAppenders()方法的同步代码块中，synchronized(this)的时候，竞争的不是同一个锁，对性能影响不大。

因此，只能“寄希望于”不同日志实例的parent，如果各个不同的日志实例是同一个对象，那么，日志的打印就“可以”对性能造成很大影响了。下面从log4j日志系统的初始化过程来证明这一点。

二、log4j初始化

Category类

首先关注核心类Category，

public class Category implements AppenderAttachable {
    //The parent of this category. All categories have at least one
    // ancestor which is the root category.
    // 当前logger的父级，所有的logger至少有一个祖先（根logger）
    volatile protected Category parent;
}

以上我们已经了解到，日志实例在打印日志时，方法callAppenders()中会循环获取其parent的锁，这里的parent就是父级logger。那么parent字段是何时初始化呢 ？

正向查找太难，在没有文档资料参考的情况下，我们不知道log4j的初始化顺序是怎样的。那么不妨逆向去找，既然重点是parent字段，那么只要看parent的赋值操作，就可以一窥端倪：

parent赋值

发现在类Hierarchy中，对parent做了赋值操作。

Hierarchy类

另一个核心类是Hierarchy，继承自接口LoggerRepository。

正如其名字一样，LoggerRepository是所有logger的仓库，用于创建以及检索logger。LoggerRepository仓库中日志logger的关系取决于仓库本身，但是通常日志logger之间的关系是以名称决定的层级结构。除了创建方法之外，已经存在的日志logger可以在LoggerRepository中查询，此外LoggerRepository也可以作为日志logger相关事件的注册表。

Hierarchy作为LoggerRepository的子类，专门用来根据名字检索日志logger以及维护日志的层次结构。 通常用户不需要与Hierarchy类打交道。

日志logger之间的层次结构依赖于 Hierarchy的getLogger()方法维护。这个层次结构中，子logger可以链接到他们的父级logger，但是父级logger不指向子logger。此外，日志logger可以以任何顺序初始化，甚至子孙logger可以在祖先logger之前初始化。

1. void updateParents(Logger)

以上是LoggerRepository类以及Hierarchy类的自说明文档。下面继续按照Category类中parent赋值的线索。

Hierarchy类中方法updateParents(Logger)对Category的parent属性做了赋值操作，这里的参数是Logger，因为Logger是Category的子类，也有parent属性：

final private void updateParents(Logger cat) {
    String name = cat.name;
    int length = name.length();
    boolean parentFound = false;

    // if name = "w.x.y.z", loop thourgh "w.x.y", "w.x" and "w", but not "w.x.y.z"
    for (int i = name.lastIndexOf('.', length - 1); i >= 0;
         i = name.lastIndexOf('.', i - 1)) {
        String substr = name.substring(0, i);

        //System.out.println("Updating parent : " + substr);
        CategoryKey key = new CategoryKey(substr); // simple constructor
        Object o = ht.get(key);
        // Create a provision node for a future parent.
        if (o == null) {
            //System.out.println("No parent "+substr+" found. Creating ProvisionNode.");
            ProvisionNode pn = new ProvisionNode(cat);
            ht.put(key, pn);
        } else if (o instanceof Category) {
            parentFound = true;
            cat.parent = (Category) o;
            //System.out.println("Linking " + cat.name + " -> " + ((Category) o).name);
            break; // no need to update the ancestors of the closest ancestor
        } else if (o instanceof ProvisionNode) {
            ((ProvisionNode) o).addElement(cat);
        } else {
            Exception e = new IllegalStateException("unexpected object type " +
                    o.getClass() + " in ht.");
            e.printStackTrace();
        }
    }
    // If we could not find any existing parents, then link with root.
    if (!parentFound)
        cat.parent = root;
}

Hierarchy中，一个名为ht的HashTable负责存储已将创建的全部节点，作为LoggerRepository的具体实现。

Hashtable ht;

该方法中，按照Logger的名字（name属性），以.分割，从右向左依次循环，直到在ht中找到类型为Category的节点，并作为当前logger的parent，如果没有找到，使用root作为parent。这里的root是Hierarchy构造函数中传递的参数logger，由调用方决定。

正如注释所示，如果name = "w.x.y.z", 那么从 "w.x.y", "w.x" 以及 "w"依次去ht中寻找类型为Category的节点作为parent。

2. Logger getLogger(String name, LoggerFactory factory)

继续线索，updateParents方法唯一被Hierarchy中的getLogger(String, LoggerFactory)调用：

public Logger getLogger(String name, LoggerFactory factory) {
    //System.out.println("getInstance("+name+") called.");
    CategoryKey key = new CategoryKey(name);
    // Synchronize to prevent write conflicts. Read conflicts (in
    // getChainedLevel method) are possible only if variable
    // assignments are non-atomic.
    Logger logger;

    synchronized (ht) {
        Object o = ht.get(key);
        if (o == null) {
            logger = factory.makeNewLoggerInstance(name);
            logger.setHierarchy(this);
            ht.put(key, logger);
            updateParents(logger);
            return logger;
        } else if (o instanceof Logger) {
            return (Logger) o;
        } else if (o instanceof ProvisionNode) {
            //System.out.println("("+name+") ht.get(this) returned ProvisionNode");
            logger = factory.makeNewLoggerInstance(name);
            logger.setHierarchy(this);
            ht.put(key, logger);
            updateChildren((ProvisionNode) o, logger);
            updateParents(logger);
            return logger;
        } else {
            // It should be impossible to arrive here
            return null;  // but let's keep the compiler happy.
        }
    }
}

首先尝试从ht中取出同名的logger：

1. 若不存在，使用工厂方法创建一个logger并加入ht，之后调用updateParents()更新logger的parent；
2. 若存在，并且是Logger类型的，直接返回；
3. 若是ProvisionNode类型，则根据名字name创建logger，加入ht，更新logger的parent。这里有一个额外的操作是更新该ProvisionNode下的所有子节点的parent为当前logger。

log4j支持子孙节点在祖先节点之前初始化的关键就是ProvisionNode。

在updateParents中，若从ht找不到name代表的父节点，则使用父节点名创建一个ProvisionNode，ProvisionNode维持一个Logger类型的列表，创建ProvisionNode时自动将logger加入列表，ProvisionNode称为logger的未来节点，在未来同名的Logger在getLogger()方法中创建时，会代替未来节点。updateParents方法总是能找到一个类型为Logger的父节点，根节点兜底。

在getLogger中，若name在ht已经作为一个ProvisionNode存在，则替换ht中同名ProvisionNode，更新当前logger父节点的同时，依赖ProvisionNode未来节点维持的列表，使用当前logger替换。

到这里已经解释了不同的logger为什么会有相同的parent了，层次机制主要由Hierarchy维持，层次越高，锁竞争越激烈。

如果一个jvm中只有一个Hierarchy结构，那么这种竞争更加激烈。

3. LogManager初始化

继续看getLogger()方法的调用者：

invoke logger

使用Logger类的静态方法getLogger()间接依赖Hierarchy的getLogger()；
其他的使用都是与log4j的初始化相关。

通过逆向调用追踪，最终在LogManager的static代码块发现了Hierarchy getLogger()的调用。

在LogManager初始化时：

1. 创建一个Hierarchy对象作为log4j的logger仓库；
2. 在约定类路径位置寻找配置文件，输出URL；
3. 根据配置文件的类型，选择DOMConfigurator或者PropertyConfigurator初始化日志系统；

[DOM,Property]Configurator初始化日志系统，其实是对logger仓库Hierarchy对象初始化。
这里我们只关注对Logger的初始化，以PropertyConfigurator为例，根据配置，若行以log4j.category.或者log4j.logger.开头，则调用Hierarchy对象的getLogger方法初始化配置的logger实例：

protected void parseCatsAndRenderers(Properties props, LoggerRepository hierarchy) {
// ...
loop props:
    if key statswith CATEGORY_PREFIX or LOGGER_PREFIX:
        Logger logger = hierarchy.getLogger(loggerName, loggerFactory);
//...
}

以上结合LogMamanger的getLogger方法，logger的创建在两个地方：

1. 手动调用创建logger实例；
2. 配置初始化时，会以log4j.category.或者log4j.logger.开头的行，创建指定名字的logger。

LogManager的static代码块保证了同一个JVM中，只会初始化一次LogManager(若不存在人为加载并初始化LogManager的情况)，从而保证一个JVM只有一个logger仓库Hierarchy对象。因此在所有的日志打印中，都会竞争日志层次结构中最顶层的logger对象锁。

三、总结

以下是log4j初始化过程中几个重要的类：

sum