logback之debug级别日志性能

logback之debug级别日志性能

主要针对问题：
1. 是否有必要使用log.isDebugEnabled
2. info级别时，debug日志即使不打印，是否会影响性能

本文不设计任何原理，只讨论结果。

实验代码如下：

public static void main(String[] args)
    {

        String str1 = "hello1";
        String str2 = "hello2";
        String str3 = "hello3";
        String str4 = "hello4";

        if (!init(DefaultValues.LOG_INDEX_INIT))
        {
            logger.error("{} initialization failure...", SERVICE_NAME);
            System.exit(0);
        }
        if (logger.isDebugEnabled())
        {
            logger.info("debug level cost:");
        }
        else if (logger.isInfoEnabled())
        {
            logger.info("info level cost:");
        }

        long startTime = System.currentTimeMillis();
        for (int i = 0; i < 100; i++)
        {
            logger.debug("i:{}, str1:{}, str2:{}, str3:{}, str4:{},", i, str1, str2, str3, str4);
        }
        logger.info("100 debug cost:{}", (System.currentTimeMillis() - startTime));

         startTime = System.currentTimeMillis();
        for (int i = 0; i < 1000; i++)
        {
            logger.debug("i:{}, str1:{}, str2:{}, str3:{}, str4:{},", i, str1, str2, str3, str4);
        }
        logger.info("1000 debug cost:{}", (System.currentTimeMillis() - startTime));

        startTime = System.currentTimeMillis();
        for (int i = 0; i < 10000; i++)
        {
            logger.debug("i:{}, str1:{}, str2:{}, str3:{}, str4:{},", i, str1, str2, str3, str4);
        }
        logger.info("10000 debug cost:{}", (System.currentTimeMillis() - startTime));

        startTime = System.currentTimeMillis();
        for (int i = 0; i < 1000; i++)
        {
            if (logger.isDebugEnabled())
            {
                logger.debug("i:{}, str1:{}, str2:{}, str3:{}, str4:{},", i, str1, str2, str3, str4);
            }
        }
        logger.info("isDebugEnabled, 1000 debug cost:{}", (System.currentTimeMillis() - startTime));

        startTime = System.currentTimeMillis();
        for (int i = 0; i < 10000; i++)
        {
            if (logger.isDebugEnabled())
            {
                logger.debug("i:{}, str1:{}, str2:{}, str3:{}, str4:{},", i, str1, str2, str3, str4);
            }
        }
        logger.info("isDebugEnabled, 10000 debug cost:{}", (System.currentTimeMillis() - startTime));

        startTime = System.currentTimeMillis();
        for (int i = 0; i < 1000; i++)
        {
            logger.info("i:{}, str1:{}, str2:{}, str3:{}, str4:{},", i, str1, str2, str3, str4);
        }
        logger.info("info cost:{}", (System.currentTimeMillis() - startTime));
    }

为了消除程序前台打印日志产生的影响，实验运行程序都是使用后台启动。
结果分别如下：

nohup info:
[2017-04-13 19:51:41.845][INFO ][main][Starter.java:103] - info level cost:
[2017-04-13 19:51:41.845][INFO ][main][Starter.java:111] - 100 debug cost:0
[2017-04-13 19:51:41.846][INFO ][main][Starter.java:118] - 1000 debug cost:1
[2017-04-13 19:51:41.852][INFO ][main][Starter.java:125] - 10000 debug cost:6
[2017-04-13 19:51:41.853][INFO ][main][Starter.java:135] - isDebugEnabled, 1000 debug cost:1
[2017-04-13 19:51:41.855][INFO ][main][Starter.java:145] - isDebugEnabled, 10000 debug cost:2
[2017-04-13 19:51:41.961][INFO ][main][Starter.java:152] - info cost:106
nohup debug:
[2017-04-13 19:46:15.946][INFO ][main][Starter.java:111] - 100 debug cost:13
[2017-04-13 19:46:16.042][INFO ][main][Starter.java:118] - 1000 debug cost:96
[2017-04-13 19:46:16.409][INFO ][main][Starter.java:125] - 10000 debug cost:367
[2017-04-13 19:46:16.432][INFO ][main][Starter.java:135] - isDebugEnabled, 1000 debug cost:23
[2017-04-13 19:46:16.659][INFO ][main][Starter.java:145] - isDebugEnabled, 10000 debug cost:227
[2017-04-13 19:46:16.683][INFO ][main][Starter.java:152] - info cost:24

结论：

1. 使用logback时，不需要代码里加isDebugEnabled，logback会自动处理
2. 使用logback时，info级别不会处理debug级别日志。

上面debug级别结果中，“isDebugEnabled, 1000”比“1000 debug”快，是由于代码顺序引起的，猜测可能是logback前期未预热，创建对象等引起耗时大。

注意：

logback中可以针对appender设置filter，过滤到某个日志级别。如下：

<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
    <level>info</level>
</filter>

此时，若日志级别为debug，该日志中不会打印debug日志，但debug日志依然会被处理，会影响性能。