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
结论:
- 使用logback时,不需要代码里加isDebugEnabled,logback会自动处理
- 使用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日志依然会被处理,会影响性能。