从源码分析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的初始化相关。

通过逆向调用追踪,最终在LogManagerstatic代码块发现了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
最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 204,684评论 6 478
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 87,143评论 2 381
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 151,214评论 0 337
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 54,788评论 1 277
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 63,796评论 5 368
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,665评论 1 281
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 38,027评论 3 399
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,679评论 0 258
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 41,346评论 1 299
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,664评论 2 321
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,766评论 1 331
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,412评论 4 321
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 39,015评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,974评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,203评论 1 260
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 45,073评论 2 350
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,501评论 2 343

推荐阅读更多精彩内容

  • 在应用程序中添加日志记录总的来说基于三个目的:监视代码中变量的变化情况,周期性的记录到文件中供其他应用进行统计分析...
    时待吾阅读 4,940评论 1 13
  • 在应用程序中添加日志记录总的来说基于三个目的:监视代码中变量的变化情况,周期性的记录到文件中供其他应用进行统计分析...
    时待吾阅读 4,957评论 0 6
  • Log4J的配置文件(Configuration File)就是用来设置记录器的级别、存放器和布局的,它可接key...
    Alex_1799阅读 45,142评论 0 11
  • 吾有三爱,日.月.卿 日是朝, 月是暮, 卿是朝朝暮暮
    稳稳的幸福_5a51阅读 111评论 0 0
  • 我要走了, 说句“再见”吧! 有些客套; 琐碎的闲聊, 掩饰了心里的忧伤! 相遇总在离别, 不求伯牙子期, 愿时光...
    梦宁阅读 222评论 2 3