当我们打开或关闭某些日志位置时,log4j实际上在做什么？

Question

我们知道我们可以通过其属性/配置文件来配置log4j以关闭特定位置(Java中的类或包)的日志.我的问题是:

1. 什么是log4j实际上为那些标志做什么？
2. log4j中的日志语句是否仍然被调用但是由于该标志而没有被写入文件或控制台？那还有性能影响吗？
3. 就像C++中的#ifdef在编译时生效那么可以限制性能影响吗？

谢谢,

Answer 1

是的,日志语句仍将执行.这就是为什么首先检查日志级别是一个很好的模式:类似的东西

if (log.isInfoEnabled()) {
    log.info("My big long info string: " + someMessage);
}

这是为了防止String在日志级别不支持INFO语句时为信息重新分配空间.

它不是什么#ifdef- #ifdef是编译器指令,而Log4J配置是在运行时处理的.

编辑:我讨厌由于无知而降级,所以这里有一篇文章支持我的答案.

来自http://surguy.net/articles/removing-log-messages.xml:

在Log4J中,如果您在DEBUG级别记录消息,并且当前的Appender设置为仅记录INFO级别及以上的消息,则不会显示该消息.调用log方法本身的性能损失很小 - 几纳秒.但是,评估log方法的参数可能需要更长时间.例如:

logger.debug("大对象是"+ largeObject.toString());

评估largeObject.toString()可能很慢,并且在调用记录器之前对其进行评估,因此即使不使用记录器,记录器也无法阻止它被评估.

编辑2:来自log4j手册本身(http://logging.apache.org/log4j/1.2/manual.html):

用户应该了解以下性能问题.

1. 关闭日志记录时的记录性能.当完全关闭日志记录或仅针对一组级别关闭日志记录时,日志请求的开销包括方法调用和整数比较.在233 MHz Pentium II机器上,此成本通常在5到50纳秒范围内.

   但是,方法调用涉及参数构造的"隐藏"成本.

   例如,对于一些记录器猫,写作,

    logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i]));
   

   导致构造消息参数的成本,即将整数i和entry [i]转换为String,并连接中间字符串,无论是否记录消息.参数构造的成本可能非常高,并且取决于所涉及的参数的大小.

   为避免参数构造成本写入:

   if(logger.isDebugEnabled() {
     logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i]));
   }
   

   如果禁用调试,这将不会产生参数构造的成本.另一方面,如果记录器是启用调试的,则会产生两倍于评估记录器是否启用的成本:一次在debugEnabled中,一次在调试中.这是一个无关紧要的开销,因为评估记录器需要大约1%的实际日志记录时间.

Answer 2

我运行了一个简单的基准测试.

    for (int j = 0; j < 5; j++) {
        long t1 = System.nanoTime() / 1000000;
        int iterations = 1000000;
        for (int i = 0; i < iterations; i++) {
            int test = i % 10;
            log.debug("Test " + i + " has value " + test);
        }
        long t2 = System.nanoTime() / 1000000;
        log.info("elapsed time: " + (t2 - t1));

        long t3 = System.nanoTime() / 1000000;
        for (int i = 0; i < iterations; i++) {
            int test = i % 10;
            if (log.isDebugEnabled()) {
                log.debug("Test " + i + " has value " + test);
            }
        }
        long t4 = System.nanoTime() / 1000000;
        log.info("elapsed time 2: " + (t4 - t3));
    }

elapsed time: 539
elapsed time 2: 17
elapsed time: 450
elapsed time 2: 18
elapsed time: 454
elapsed time 2: 19
elapsed time: 454
elapsed time 2: 17
elapsed time: 450
elapsed time 2: 19

随着1.6.0_18,这让我感到惊讶,因为我认为内联会阻止这一点.也许带有逃逸分析的Java 7会.

但是我仍然不会将调试语句包装在if子句中,除非半微秒的时间改进变得很重要!