Skip to content

logback blocked the logic thread

Jump to bottom
landon edited this page Jun 27, 2019 · 2 revisions

某卡牌游戏留存测试第一天玩家反馈卡顿问题排查

现象

  1. 2019.04.25 10:00开服
  2. 1小时内，同时在线达到2000
  3. 服务器CPU正常，30-40左右
  4. 玩家反馈操作转菊花，而且越来越频繁

排查

  1. 初步怀疑是否是逻辑线程blocked了
  2. 使用jstack和top -Hp命令排查了一下占用cpu较高的线程堆栈
"AsyncAppender-Worker-ASYNC-SIFT" #1180 daemon prio=5 os_prio=0 tid=0x00007fc5f0007800 nid=0x2015 runnable [0x00007fc6720b8000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000005b887c460> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
        at java.util.concurrent.ArrayBlockingQueue.take(ArrayBlockingQueue.java:403)
        at ch.qos.logback.core.AsyncAppenderBase$Worker.run(AsyncAppenderBase.java:289)
  1. 发现了logback这个异步线程，一是使用了ArrayBlockingQueue，而是发现在take，说明之前一直在快速的处理日志队列消息，然后队列为空，在等待消息
  2. 那么直接怀疑是否是因为逻辑线程向logback异步日志，写到ArrayBlockingQueue。而ArrayBlockingQueue的入队和出队共用一把锁，入队和出队存在竞争，一方速度高时另一方速度会变低,即逻辑线程在向logback的异步队列写日志的时候，获取锁的时候被阻塞了一下。

临时解决方案

  1. 将网络层的request/response的net日志的debug改为info，自动reload
  2. 整个世界都安静了
Clone this wiki locally