logger打得太多是否影响效率

前言

今天朋友问了一个问题，logger打的太多，是否影响效率，说实话，平常这方面了解得不太多，所以上网搜了搜，找到一篇写得挺不错的文章，简洁，但说得很清楚，特此记录下来

日志影响效率问题分析原文 (opens new window)

问题发现

1. 将一台docker上其他服务都进行下线，同时将其他docker上的A服务进行下线，也就是说调用方只能调用到该docker上的A服务。这个时候发现除了A服务性能比较差，其他服务基本恢复正常。

2. 将A服务的每一步认为耗时的地方都加上日志打印，包括内部方法调用的地方。这时候发现一个奇怪，在方法methodA()的内部耗时打印日志是10ms，在this.methodA()调用的地方耗时打印日志是1000ms；而且查看依赖的两个外部服务的性能都比较正常，所以加上日志打印后也看不出来到底是什么地方耗时。

3. 再次梳理代码，能考虑到的地方都考虑到了，依然没有任何解决方案。

4. 考虑是否是日志打印太多导致了该问题，因为log4j在多线程情况下，会竞争Logger的锁。下载线程快照文件后（执行jstatck -l pid），文件部分内容如下图所示，看了一下，差不多大概有200个线程都是blocked状态，都在等待这把锁：

5. 将A服务内所有打印日志的地方都注释掉，然后重启，此时性能恢复。
6. 查看监控得知，当时A服务由平时200/m的调用量突然彪到了5000/m的调用量。且A服务内部有很多不合理的日志打印，所以导致了这次线上问题。
7. 那回到最开始，为什么会影响docker上的其他服务呢。因为A服务和其他服务共用了一个线程池（200个），当大量A请求过来，且很多线程都阻塞的情况下，导致了其他服务没有线程可用，所以影响了到其他服务。那这时的解决方案就是在设计初期要做线程隔离的规划，关于高并发系统的各种隔离策略可以参见 (opens new window)

Log4j分析

我们来看一下log4j的内部实现，查看如下源代码。可以简单理解为当写入同一个日志文件时（如调用log.info(xxx)，会写入info.log文件），为了保证写入文件的顺序不错乱，会对该资源加锁。

public void callAppenders(LoggingEvent event) {
  int writes = 0;

  for(Category c = this; c != null; c = c.parent) {
    synchronized(c) {
      if(c.aai != null) {
        writes += c.aai.appendLoopOnAppenders(event);
      }

      if(!c.additive) {
        break;
      }
    }
  }

  if(writes == 0) {
    this.repository.emitNoAppenderWarning(this);
  }
}

总结

1. 日志打印要有针对性，不该打的日志不打，该打的日志一定要打，且要有一定的打印规范。

2. 线上日志级别调到最高，一般开启的info级别

3. 如果碰到如下情况，如 LOG.info("params = {}", JSON.toJSONString(user));如下打印需求，可以修改为如下打印方式，因为你不加的话，其实JSON序列化也执行了，所以为了不必要的性能损耗，前面可以加上判断。

   if (LOG.isInfoEnable) {
   	LOG.info("params = {}", JSON.toJSONString(user));
   }
   

4、可以采用logback、log4j2来替换log4j。

logback、log4j2、log4j性能对比

单线程：外循环100次，内循环100000次；

多线程：开启100个线程，每个线程执行100000次；

日志框架性能比较原文 (opens new window)

JAVA代码

• Log4j

public class log4jDemo {

    Logger logger = Logger.getLogger(log4jDemo.class);

    @Test
    public void testThread() throws InterruptedException {
        int THREAD_NUM = 100;
        final int LOOP_NUM = 100000;

        final CountDownLatch countDownLatch = new CountDownLatch(THREAD_NUM);
        long start = System.currentTimeMillis();
        for(int x= 0;x < THREAD_NUM;x++){
            new Thread(new Runnable() {
                public void run() {
                    for (int y = 0; y < LOOP_NUM; y++) {
                        logger.info("Info Message!");
                    }
                    countDownLatch.countDown();
                }
            }).start();
        }
        countDownLatch.await();
        System.out.println(System.currentTimeMillis() - start);
    }

    @Test
    public void test() throws InterruptedException {
        int X_NUM = 100;
        int Y_NUM = 100000;

        long start = System.currentTimeMillis();
        for(int x=0;x < X_NUM;x++) {
            for (int y = 0; y < Y_NUM; y++) {
                logger.info("Info Message!");
            }
        }
        System.out.print(System.currentTimeMillis() - start);
    }
}

• logback

public class logbackDemo {

    Logger logger =  LoggerFactory.getLogger(logbackDemo.class);

    @Test
    public void testThread() throws InterruptedException {
        int THREAD_NUM = 100;
        final int LOOP_NUM = 100000;

        final CountDownLatch countDownLatch = new CountDownLatch(THREAD_NUM);
        long start = System.currentTimeMillis();
        for(int x= 0;x < THREAD_NUM;x++){
            new Thread(new Runnable() {
                public void run() {
                    for (int y = 0; y < LOOP_NUM; y++) {
                        logger.info("Info Message!");
                    }
                    countDownLatch.countDown();
                }
            }).start();
        }
        countDownLatch.await();
        System.out.println(System.currentTimeMillis() - start);
    }

    @Test
    public void test() {
        int X_NUM = 100;
        int Y_NUM = 100000;

        long start = System.currentTimeMillis();
        for(int x=0;x<X_NUM;x++) {
            for (int y = 0; y < Y_NUM; y++) {
                logger.info("Info Message!");
            }
        }
        System.out.print(System.currentTimeMillis()-start);
    }
}

• log4j2

public class log4j2Demo {
    private Logger logger = LogManager.getLogger(log4j2Demo.class);

    @Test
    public void testThread() throws InterruptedException {
        int THREAD_NUM = 100;
        final int LOOP_NUM = 100000;

        final CountDownLatch countDownLatch = new CountDownLatch(THREAD_NUM);
        long start = System.currentTimeMillis();
        for(int x= 0;x < THREAD_NUM;x++){
            new Thread(new Runnable() {
                public void run() {
                    for (int y = 0; y < LOOP_NUM; y++) {
                        logger.info("Info Message!");
                    }
                    countDownLatch.countDown();
                }
            }).start();
        }
        countDownLatch.await();
        System.out.println(System.currentTimeMillis() - start);
    }
    
    @Test
    public void test() throws InterruptedException {
        int X_NUM = 100;
        int Y_NUM = 100000;

        long start = System.currentTimeMillis();
        for(int x=0;x<X_NUM;x++) {
            for (int y = 0; y < Y_NUM; y++) {
                logger.info("Info Message!");
            }
        }
        System.out.print(System.currentTimeMillis() - start);
    }
}

配置文件

• log4j

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration>

    <!--无缓存，立即输出-->
    <appender name="FILE" class="org.apache.log4j.FileAppender">
        <param name="File" value="e:/log.out" />
        <param name="append" value="true"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d{HH:mm:ss.SSS} %p %c - %m%n" />
        </layout>
    </appender>

    <!--有缓存，不立即输出-->
    <appender name="FILE" class="org.apache.log4j.FileAppender">
        <param name="File" value="e:/log.out" />
        <param name="append" value="true"/>
        <param name="immediateFlush" value="false"/>
        <param name="bufferedIO" value="true"/>
        <param name="bufferSize" value="8192"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d{HH:mm:ss.SSS} %p %c - %m%n" />
        </layout>
    </appender>

    <!--异步appender-->
    <appender name="AsyncAppender" class="org.apache.log4j.AsyncAppender">
        <appender-ref ref="FILE"/>
    </appender>

    <root>
        <priority value="info" />
        <appender-ref ref="FILE" />
        <appender-ref ref="AsyncAppender" />
    </root>
</log4j:configuration>

• logback

<configuration >

    <!--无缓存，立即输出-->
    <appender name="FILE" class="ch.qos.logback.core.FileAppender">
        <file>e:/log.out</file>
        <append>true</append>
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} %p %c - %m%n</pattern>
        </encoder>
    </appender>

    <!--有缓存，不立即输出-->
    <appender name="FILE" class="ch.qos.logback.core.FileAppender">
        <file>e:/log.out</file>
        <append>true</append>
        <immediateFlush>false</immediateFlush>
        <bufferSize>8192</bufferSize>
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} %p %c - %m%n</pattern>
        </encoder>
    </appender>

    <!--异步appender-->
    <appender name ="ASYNC" class= "ch.qos.logback.classic.AsyncAppender">  
        <discardingThreshold>0</discardingThreshold>  
        <queueSize>128</queueSize>  
        <appender-ref ref ="FILE"/>  
    </appender>  
    
    <root level="info">
        <appender-ref ref="ASYNC" />
        <appender-ref ref="FILE" />
    </root>
</configuration>

• log4j2

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="info" monitorInterval="30">
    <Appenders>

        <!--无缓存，立即输出-->
       <File name="File" fileName="e:/log.out" append="true">
            <<PatternLayout>
                <Pattern>%d{HH:mm:ss.SSS} %p %c - %m%n</Pattern>
            </PatternLayout>
        </File>

        <!--有缓存，不立即输出-->
        <File name="File" fileName="e:/log.out" append="true"
              immediateFlush="false" bufferedIO="true" bufferSize="8192">
            <PatternLayout>
                <Pattern>%d{HH:mm:ss.SSS} %p %c - %m%n</Pattern>
            </PatternLayout>
        </File>

       <!--异步appender-->
        <Async name="Async">
            <AppenderRef ref="File"/>
        </Async>
    </Appenders>
    <Loggers>
        <Root level="info" >
            <AppenderRef ref="Async"/>
            <AppenderRef ref="File"/>
        </Root>
        <!--异步logger-->
        <AsyncRoot level="info" >
            <AppenderRef ref="File"/>
        </AsyncRoot>
    </Loggers>
</Configuration>

结果比较（毫秒）

• 单线程

  （1）单线程，未开启缓存，立即刷出
  
  log4j：29772、29959、30911
  
  logback：25423、24552、26006
  
  log4j2：37927、38240、40164
  
  （2）单线程，开启缓存，不立即刷出
  
  log4j：9858、9677、9665
  
  logback：5561、5604、5611
  
  log4j2：5782、5505、5499
  
  （3）单线程，异步appender,未开启缓存，立即输出
  
  log4j：29683、29929、29385
  
  logback：33102、31779、30516
  
  log4j2：39298、39562、41872
  
  （4）单线程，异步appender，开启缓存，不立即输出
  
  log4j：10110、10068、10177
  
  logback：8753、9112、8922
  
  log4j2：8692、8400、8252
  
  

• 多线程

  （1）多线程，未开启缓存，立即刷出
  
  log4j：38541、37791、38366
  
  logback：35644、35463、35442
  
  log4j2：38544、38746、38706
  
  （2）多线程，开启缓存，不立即刷出
  
  log4j：13296、12938、12686
  
  logback：6547、6294、6576
  
  log4j2：5596、5423、5421
  
  （3）多线程，异步appender,未开启缓存，立即输出
  
  log4j：30844、32088、30734
  
  logback：44203、42191、43228
  
  log4j2：46804、46034、46232
  
  （4）多线程，异步appender，开启缓存，不立即输出
  
  log4j：10422、10204、10495
  
  logback：40249、40437、40173
  
  log4j2：7832、8447、8660
  
  （5）多线程，异步logger，未开启缓存，立即输出
  
  log4j2：40555、40245、40325
  
  
  （6）多线程，异步logger，开启缓存，不立即刷出
  
  log4j2：5319、5407、5305
  

结论

• 无论是多线程还是单线程，在启用缓存的情况下，系统性能得到了巨大的提升；

• 在单线程情况下，相比较来说，启用异步Appender并没有对性能有较大的提升！

• 值得一提的是，在log4j2中，多线程情况下，相对于同步logger来说，异步logger并没有进一步提高系统的性能，两者不相上下；

• 但是，对于其他情况而言，异步logger还是有较大的提升！