高并发系统谨防被一行日志击垮

一、同步打印日志中的坑

1.1 高并发场景下 logback 造成线程泄露

调用 logback 去打印日志的时候是会加锁的，加锁的位置在：

// ch.qos.logback.core.OutputStreamAppender#writeBytesprivate void writeBytes(byte[] byteArray) throws IOException {
      if (byteArray != null && byteArray.length != 0) {
          this.lock.lock();        try {
              this.outputStream.write(byteArray);            if (this.immediateFlush) {
                  this.outputStream.flush();            }        } finally {
              this.lock.unlock();        }
    }}

复制代码

这就意味着同一个 appender 的日志写是串行的，在高并发的场景下因为有锁的争用现象，所以看似很简单的一行日志，耗费的时间却不少。接下来我们在本地简单的模拟一下高并发的场景，并记录打一行日志的耗时是多少

public static void main(String[] args) {
      ExecutorService threadPool = new ThreadPoolExecutor(500, 750, 20, TimeUnit.MINUTES, new ArrayBlockingQueue<>(1),                                                        new ThreadFactoryBuilder().setNameFormat("test-log-thread").build(), new ThreadPoolExecutor.CallerRunsPolicy());    for (int i = 0; i < 750; i++) {
          LoggerExecutor commonExecutor = new LoggerExecutor();        threadPool.submit(commonExecutor);    }}static class LoggerExecutor implements Runnable {
      @SneakyThrows    @Override    public void run() {
          while (true) {
              long start = System.currentTimeMillis();            logger.info("log info message at {}", System.currentTimeMillis());            long end = System.currentTimeMillis();            long time = end - start;            System.out.println(time);        }    }}

复制代码

需要说明的是，现实中高并发的请求应当用一个线程池向另一个线程池反复提交任务来模拟，这里我们简化了这个过程。