isInfoEnabled究竟多有用？

前段时间，公司里组织了一次代码检查，其中有一条检查项让我有些费解：

所有INFO和DEBUG级别的日志，必须加上isInfoEnabled和isDebugEnabled的判断。

理由是大量的不输出的日志对性能会有影响（日志中存在字符串拼接）。如果说只是DEBUG的加上，我也就认了，可是在系统中写成INFO的日志如果不输出，那还写它干嘛，我就是想看到关键路径的日志。而且在大多数日志上加上这么一个判断真的很难看。。。

 

所谓上有政策，下有对策，于是有人开始写一些包装了判断的辅助类，当中用这样的代码（截取）：

public class LogUtil {

    public static void info(Logger logger, String message) {
        if (logger.isInfoEnabled()) {
            logger.info(message);
        }
    }

    public static void debug(Logger logger, String message) {
        if (logger.isDebugEnabled()) {
            logger.debug(message);
        }
    }

    public static void debug(Logger logger, String message, Throwable throwable) {
        if (logger.isDebugEnabled()) {
            logger.debug(message, throwable);
        }
    }
}

但这样的代码真的就能解决问题了吗？答案是“不能”！字符串拼接还存在。

 

那让我们分两个部分来看一下这个问题：

1. 日志中的字符串拼接真的对性能影响很大吗
2. 加不加isInfoEnabled的性能差距究竟有多少

关于第一个问题，String的拼接是不修改原来的字符串的，而是创建一个新的String对象，道理上是这么说的，我们也该这么理解。但Java编译器并不傻，实际情况是怎么样的呢，它会做些优化。请看如下代码：

public class StringAddDemo {
    public static void main(String[] args) {
        String a = "abc";
        String b = a + "def";
        System.out.println(b + "ghi");
    }
}

在编译后，通过javap -c StringAddDemo看看结果：

javap结果

Compiled from "StringAddDemo.java"
public class StringAddDemo extends java.lang.Object{
public StringAddDemo();
  Code:
   0:   aload_0
   1:   invokespecial   #1; //Method java/lang/Object."<init>":()V
   4:   return

public static void main(java.lang.String[]);
  Code:
   0:   ldc     #2; //String abc
   2:   astore_1
   3:   new     #3; //class java/lang/StringBuilder
   6:   dup
   7:   invokespecial   #4; //Method java/lang/StringBuilder."<init>":()V
   10:  aload_1
   11:  invokevirtual   #5; //Method java/lang/StringBuilder.append:(Ljava/lang/
String;)Ljava/lang/StringBuilder;
   14:  ldc     #6; //String def
   16:  invokevirtual   #5; //Method java/lang/StringBuilder.append:(Ljava/lang/
String;)Ljava/lang/StringBuilder;
   19:  invokevirtual   #7; //Method java/lang/StringBuilder.toString:()Ljava/la
ng/String;
   22:  astore_2
   23:  getstatic       #8; //Field java/lang/System.out:Ljava/io/PrintStream;
   26:  new     #3; //class java/lang/StringBuilder
   29:  dup
   30:  invokespecial   #4; //Method java/lang/StringBuilder."<init>":()V
   33:  aload_2
   34:  invokevirtual   #5; //Method java/lang/StringBuilder.append:(Ljava/lang/String;)Ljava/lang/StringBuilder;
   37:  ldc     #9; //String ghi
   39:  invokevirtual   #5; //Method java/lang/StringBuilder.append:(Ljava/lang/String;)Ljava/lang/StringBuilder;
   42:  invokevirtual   #7; //Method java/lang/StringBuilder.toString:()Ljava/lang/String;
   45:  invokevirtual   #10; //Method java/io/PrintStream.println:(Ljava/lang/String;)V
   48:  return

}

实际这里的拼接用的是StringBuilder.append。情况没想的这么糟糕，而且1000次字符串拼接的开销都比不上一次远程调用的开销大，与其想着从这里挤性能，还不如去优化远程调用和数据库访问。

 

第二点，同样用实验来做说明，这里对比了使用辅助类，使用isInfoEnabled判断和不使用判断的情况，日志级别为INFO，另外再加了使用辅助类，使用isDebugEnabled判断和不使用判断的情况，都是循环输出20万次，每次的拼接在最后都加了些运算：

public class LogDemo {
    private static final Logger logger = LoggerFactory.getLogger(LogDemo.class);

    public static void main(String[] args) {
        Profiler.start();

        Profiler.enter("Ignore");
        for (int i = 0; i < 200000; i++) {
            LogUtil.info(logger, "test" + "test" + i + i*2);
        }
        Profiler.release();
        
        Profiler.enter("InfoUtil");
        for (int i = 0; i < 200000; i++) {
            LogUtil.info(logger, "test1" + "test2" + i + i*2);
        }
        Profiler.release();

        Profiler.enter("isInfoEnabled");
        for (int i = 0; i < 200000; i++) {
            if (logger.isInfoEnabled()) {
                logger.info("test3" + "test4" + i + i*2);
            }
        }
        Profiler.release();

        Profiler.enter("info");
        for (int i = 0; i < 200000; i++) {
            logger.info("test5" + "test6" + i + i*2);
        }
        Profiler.release();
        
        Profiler.enter("DebugUtil");
        for (int i = 0; i < 200000; i++) {
            LogUtil.debug(logger, "test7" + "test8" + i + i*2);
        }
        Profiler.release();

        Profiler.enter("isDebugEnabled");
        for (int i = 0; i < 200000; i++) {
            if (logger.isDebugEnabled()) {
                logger.debug("test9" + "test0" + i + i*2);
            }
        }
        Profiler.release();

        Profiler.enter("debug");
        for (int i = 0; i < 200000; i++) {
            logger.debug("tes1" + "tes2" + i + i*2);
        }
        Profiler.release();

        Profiler.release();
        System.out.println(Profiler.dump());
    }
}

（ 说明：这里的Profiler类是个工具类，作用是记录调用的时间；代码有截取；第一个循环主要是预热一下，不在统计范围内）

 

经过了几次测试，结果如下：

实验结果

+---14,766 [15,171ms, 26%, 26%] - InfoUtil
+---29,937 [14,187ms, 24%, 24%] - isInfoEnabled
+---44,124 [13,938ms, 24%, 24%] - info
+---58,062 [31ms, 0%, 0%] - DebugUtil
+---58,093 [16ms, 0%, 0%] - isDebugEnabled
`---58,109 [46ms, 0%, 0%] - debug

+---14,968 [14,656ms, 25%, 25%] - InfoUtil
+---29,624 [14,141ms, 24%, 24%] - isInfoEnabled
+---43,765 [14,265ms, 25%, 25%] - info
+---58,030 [47ms, 0%, 0%] - DebugUtil
+---58,077 [0ms] - isDebugEnabled
`---58,077 [47ms, 0%, 0%] - debug

+---14,999 [14,922ms, 26%, 26%] - InfoUtil
+---29,921 [14,093ms, 24%, 24%] - isInfoEnabled
+---44,014 [14,219ms, 24%, 24%] - info
+---58,233 [47ms, 0%, 0%] - DebugUtil
+---58,280 [0ms] - isDebugEnabled
`---58,280 [47ms, 0%, 0%] - debug

+---14,656 [14,812ms, 26%, 26%] - InfoUtil
+---29,468 [14,344ms, 25%, 25%] - isInfoEnabled
+---43,812 [13,890ms, 24%, 24%] - info
+---57,702 [31ms, 0%, 0%] - DebugUtil
+---57,733 [16ms, 0%, 0%] - isDebugEnabled
`---57,749 [47ms, 0%, 0%] - debug

+---16,219 [16,719ms, 25%, 25%] - InfoUtil
+---32,938 [17,703ms, 27%, 27%] - isInfoEnabled
+---50,641 [15,157ms, 23%, 23%] - info
+---65,798 [47ms, 0%, 0%] - DebugUtil
+---65,845 [0ms] - isDebugEnabled
`---65,845 [47ms, 0%, 0%] - debug

（数据说明：第一列为开始计时的时间点，[]内为时间及统计，15,171ms为该阶段的具体耗时，后面的百分比是该阶段耗时在这个统计内所占的百分比）

 

 对上述数据分析后，可以得到这样的结论：

1. 日志输出前的判断确实有效，但效果甚微
2. 在日志级别较低，不会输出的情况下，日志的耗时基本可以忽略 ，20万次的调用耗时在50ms内
3. 在日志级别满足输出要求时，3种方法差别不大

针对第3条再做些补充说明，日志输出大的开销应该在IO上，计算应该不会很多，也不该很多，如果存在大量的运算请自己考虑下是不是有问题；既然是确认要输出的日志，那增加判断其实是种浪费，虽然这种判断的开销可以忽略。

 

综上所述，个人建议在日常系统中无需对日志增加isInfoEnabled判断，想通过这种处理来优化效果的作用不会很明显，还是把精力从日志移到数据库和远程调用上效果更好些。 （特殊情况下，如果在日志中有复杂的操作，可以酌情考虑，但个人不倾向于复杂的日志）

 

评论

12 楼 jin8000608172 2015-01-21  

Profiler类是自己写的还是开源jar里面的，如果是开源jar包 那是哪个jar呢？

11 楼 bevis.cn 2011-09-09  

好像是高版本的jdk对字符串连接“+”做了优化的，原来好像不是的。

10 楼 zhangna307 2011-04-14  

我也杯具的现在要加上这些判断。。。要求。。。

9 楼 hareamao 2010-06-28  

mercyblitz 写道

hareamao 写道

AOP可以精细到某一行代码前后了吗？仅仅是函数级别没有什么意义。

完全可以啊。关键看你怎么拦截。

能给个例子看看吗？另外，还好看么？

8 楼 mercyblitz 2010-06-28  

hareamao 写道

mercyblitz 写道

hareamao 写道

DigitalSonic 写道

是的，我也同意，不加这个判断，对代码的可读性很有好处，文章中我也说了，加这个很难看。
关于Log4j里是否默认有这个判断，不是每个系统都能用新版本，而且日志实现很多，也不一定直接用Log4j，比如我们在项目里用的就是公司自己封装过的。

反正我现在已经放弃了这种检查了，因为实在太难看了，影响代码阅读，性能就将就一下吧。

用AOP的方式就不难看了。

AOP可以精细到某一行代码前后了吗？仅仅是函数级别没有什么意义。

完全可以啊。关键看你怎么拦截。

7 楼 hareamao 2010-06-28  

mercyblitz 写道

hareamao 写道

DigitalSonic 写道

是的，我也同意，不加这个判断，对代码的可读性很有好处，文章中我也说了，加这个很难看。
关于Log4j里是否默认有这个判断，不是每个系统都能用新版本，而且日志实现很多，也不一定直接用Log4j，比如我们在项目里用的就是公司自己封装过的。

反正我现在已经放弃了这种检查了，因为实在太难看了，影响代码阅读，性能就将就一下吧。

用AOP的方式就不难看了。

AOP可以精细到某一行代码前后了吗？仅仅是函数级别没有什么意义。

6 楼 mercyblitz 2010-06-28  

hareamao 写道

DigitalSonic 写道

是的，我也同意，不加这个判断，对代码的可读性很有好处，文章中我也说了，加这个很难看。
关于Log4j里是否默认有这个判断，不是每个系统都能用新版本，而且日志实现很多，也不一定直接用Log4j，比如我们在项目里用的就是公司自己封装过的。

反正我现在已经放弃了这种检查了，因为实在太难看了，影响代码阅读，性能就将就一下吧。

用AOP的方式就不难看了。

5 楼 hareamao 2010-06-28  

DigitalSonic 写道

是的，我也同意，不加这个判断，对代码的可读性很有好处，文章中我也说了，加这个很难看。
关于Log4j里是否默认有这个判断，不是每个系统都能用新版本，而且日志实现很多，也不一定直接用Log4j，比如我们在项目里用的就是公司自己封装过的。

反正我现在已经放弃了这种检查了，因为实在太难看了，影响代码阅读，性能就将就一下吧。

4 楼 DigitalSonic 2010-06-28  

mercyblitz 写道

 public
  void debug(Object message) {
    if(repository.isDisabled(Level.DEBUG_INT))
      return;
...

在 Log4j 1.2.15中，其实源代码中已经判断是否开放了debug等权限。

还有一点，楼主可能没有注意，在低版本的实现中，可能没有加这个类似的判断，并且可读性更好。

是的，我也同意，不加这个判断，对代码的可读性很有好处，文章中我也说了，加这个很难看。
关于Log4j里是否默认有这个判断，不是每个系统都能用新版本，而且日志实现很多，也不一定直接用Log4j，比如我们在项目里用的就是公司自己封装过的。

3 楼 mercyblitz 2010-06-28  

 public
  void debug(Object message) {
    if(repository.isDisabled(Level.DEBUG_INT))
      return;
...

在 Log4j 1.2.15中，其实源代码中已经判断是否开放了debug等权限。

还有一点，楼主可能没有注意，在低版本的实现中，可能没有加这个类似的判断，并且可读性更好。

2 楼 DigitalSonic 2010-06-28  

如果真有这种情况，还是加上避免大的性能浪费。但就像我说的，日志代码里不应该出现大量的运算或者复杂的操作，是不是真的有必要在日志里特意调用数据库，这个本身就值得商榷。

1 楼 hareamao 2010-06-28  

如果日志字串拼接的时候需要jdbc调用呢？