1. Home
  2. 代码
  3. Java

一次应用线程阻塞问题排查–log4j版本升级的坑

    今天早上刚发了版本不到半个小时的时间,接到客户的反馈,网站反应很慢,或者根本就没有反应。赶紧重启应用,重启好后,问题似乎解决了,但是才开心了不到半个小时,又发生了这个问题,赶紧打开应用的监控站点,就发现有一台机器有300多个线程发生阻塞,凡是打到这台机器上的请求均没有反应了,打到其他两台机器上的请求正常返回,然后赶紧使用jstack -l > /data/logs/thread.log命令将这台机器上的线程信息打印出来。如下图:

线程信息

发现好多阻塞的线程都是阻塞在log4j的日志组件上在。接着看了下log4j的版本是1.x,1.x的log4j在多个线程使用同一个logger时,会进行加锁,如下:

Categor.java

log4j代码

这个锁在高并发的场景下非常容易阻塞业务进程。因此,我们准备将版本升级到2.x,我们选择了2.3版本,该版本实现了无锁异步日志系统,在多线程的程序中,异步的日志系统吞吐量比log4j1.x高10,听起来很美是不是?但是后面有次版本迭代后,发现当上游的请求量特别高的时候,还是会发生应用没有反应,通过监控系统发现,cpu达到了100%,使用jstack -l > /data/logs/thread.log将线程的信息打印出来,发现处于RUNABLE状态的只有50多个,有1000多个线程处于下面的状态:

“pool-6-thread-14380” prio=10 tid=0x00007f7087594000 nid=0x53e1 runnable [0x00007f6b67bfc000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:349)
at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:136)
at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:105)
at com.lmax.disruptor.RingBuffer.publishEvent(RingBuffer.java:502)
at org.apache.logging.log4j.core.async.AsyncLoggerConfigHelper.callAppendersFromAnotherThread(AsyncLoggerConfigHelper.java:342)
at org.apache.logging.log4j.core.async.AsyncLoggerConfig.callAppenders(AsyncLoggerConfig.java:114)

线程都跑在LockSupport.java:349,

unsafe.park(false, 1);

推测是大量线程短时间频繁的sleep造成了大量的线程切换,接着做了个实验:
public static void contextSwitchTest(int threadCount) throws Exception {
  ExecutorService executorService = Executors.newFixedThreadPool(threadCount);
  for (int i = 0; i < threadCount; i++) {
    executorService.execute(new Runnable() {
      @Override
      public void run() {
        while (true) {
          LockSupport.parkNanos(1);
        }
      }
    });
  }
  executorService.awaitTermination(Long.MAX_VALUE, TimeUnit.SECONDS);
}
当线程越来越多时,就会造成大量的线程切换。而且当线程少的时候,产生日志的速度还行,当线程慢慢增多时,产生日志的速度就越来越慢,最后跟踪源码发现是在消费者消费的速度跟不上生产者生产的速度时,生产线程做了无限重试,重试间隔为1 nano,这个1 nano 会导致线程被频繁休眠/唤醒,造成kernal cpu 利用率高,context switch已经达到了cpu的极限,进而导致写log的线程的线程获取cpu时间少,吞吐量下降。后来将版本换成了2.7问题就解决了。

作者:catchdream,如若转载,请注明出处:https://www.6r6.cc/code/1210.html
文章内容包括PDF与软件、文章图片等内容来自于互联网、若您下载了本站分享的软件、PDF等内容下载后请于24小时内删除、与本站无任何关联、本站所有内容基于个人学习,勿做任何非法使用、本站也不传播非法内容、谢谢合作!若有侵权请联系我们下架处理-GD-sec诡道网络诡道安全

Leave a Reply

Your email address will not be published. Required fields are marked *

two × 3 =