新功能开发测试完成后，准备发布上线，当发布完第三台机器时，监控显示其中一台机器 CPU 突然飙升到 300%，Dubbo 活动线程数直接飙到 1000+，不得不停止发布，立马回滚出问题的机器，回滚之后恢复正常；继续观察另外两台已经发布的机器，最终，无一幸免，只能全部回滚了。
下面是我的故障排查过程：
监控日志分析
首先查看故障时间点的应用日志，发现大量方法耗时较久，其中 filterMission 方法尤为显著，耗时长达 30S+。说明下，filterMission 是当前服务中 QPS 较高的接口（日均调用量 2 个亿），所以导致故障的可能性也较高。于是重新 review 了一遍 filterMission 的实现，其中并无复杂的计算逻辑，没有大量数据的处理逻辑，也不存在锁的争用，本次需求更是不涉及 filterMission 的改造，排除 filterMission 导致故障发生。
从日志中也可以发现，大量请求发生超时，这些都只能说明系统负载过重，并不能定位问题的症结所在。
Code Review
从应用日志找不到原因所在，只能再做一次 code review 了。首先检查系统中是否存在同步代码逻辑的使用，主要是为了排除发生死锁的可能；检查具有复杂运算逻辑的代码；同时，将本次修改的代码和上一版本进行比对，也没找出什么问题。（事实证明，Review 不够仔细）
线程 Dump 分析
到此，从日志中暂时也分析不出问题，盲目看代码也无法具体定位问题了，现在只能重新发布一台机器，出现问题时让运维将应用程序的线程堆栈 dump 出来，分析 jstack 文件。开始分析 dump 文件前，先巩固下基础吧。
线程状态
图中各状态说明：
New: 新建状态，当线程对象创建时存在的状态；
Runnable：ready-to-run，可运行状态，调用 thread.start()后，线程变成为 Runnable 状态，还需要获得 CPU 才能运行；
Running：正在运行，当调用 Thread.yield()或执行完时间片，CPU 会重新调度；注意：Thread.yield()调用之后，线程会释放 CPU，但是 CPU 重新调度可能让线程重新获得时间片。
Waiting：调用 thread.join()、object.wait()和 LockSupport.park()线程都会进入该状态，表明线程正处于等待某个资源或条件发生来唤醒自己；thread.join()、object.wait()需要 Object 的 notify()/notifyAll()或发生中断来唤醒，LockSupport.park()需要 LockSupport.unpark()来唤醒，这些方法使线程进入 Runnable 状态，参与 CPU 调度。
thread.join()：作用是等待线程 thread 终止，只有等 thread 执行完成后，主线程才会继续向下执行；从 join()实现可知，主线程调用 thread.join()之后，只有 thread.isAlive()返回 true，才会调用 object.wait()使主线程进入等待状态，也就是说，thread.start()未被调用，或 thread 已经结束，object.wait()都不会被调用。也就是说，必须先启动线程 thread，调用 thread.join()才会生效；若主线程在 waiting 状态被唤醒，会再次判断 thread.isAlive()，若为 true，继续调用 object.wait()使进入 waiting 状态，直到 thread 终止，thread.isAlive()返回 false。
object.wait()：作用是使线程进入等待状态，只有线程持有对象上的锁，才能调用该对象的 wait()，线程进入等待状态后会释放其持有的该对象上的锁，但会仍然持有其它对象的锁。若其他线程想要调用 notify()、notifyAll()唤醒该线程，也需要持有该对象的锁。
LockSupport.park()：挂起当前线程，不参与线程调度，除非调用 LockSupport.unpark()重新参与调度。
Timed_Waiting：调用 Thread.sleep(long)、LockSupport.parkNanos(long)、thread.join(long)或 obj.wait(long)等都会使线程进入该状态，与 Waiting 的区别在于 Timed_Waiting 的等待有时间限制；
Thread.sleep()：让当前线程停止运行指定的毫秒数，该线程不会释放其持有的锁等资源。
Blocked：指线程正在等待获取锁，当线程进入 synchronized 保护的代码块或方法时，没有获取到锁，则会进入该状态；或者线程正在等待 I/O，也会进入该状态。注意，java 中 Lock 对象不会使线程进入该状态。
Dead：线程执行完毕，或者抛出了未捕获的异常之后，会进入 dead 状态，表示该线程结束。
上图中某些状态只是为了方便说明，实际并不存在，如 running/sleeping，java 中明确定义的线程状态值有如下几个：
NEW、RUNNABLE、BLOCKED、WAITING、TIMED_WAITING、TERMINATED
分析 jstack 日志
"DubboServerHandler-172.24.16.78:33180-thread-1220" #1700 daemon prio=5 os_prio=0 tid=0x00007f3394988800 nid=0x4aae waiting on condition [0x00007f32d75c0000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000000866090c0> (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.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1081) at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745)
复制代码
由日志可知道，线程“DubboServerHandler-172.24.16.78:33180-thread-1220”处于 WAITING 状态，主要原因是线程从线程池队列中取任务来执行，但线程池为空，最终调用了 LockSupport.park 使线程进入等待状态，需要等待队列非空的通知。
设想一下，什么时候会新创建新线程来处理请求？结合 jdk 线程池实现可知，当新请求到来时，若池中线程数量未达到 corePoolSize，线程池就会直接新建线程来处理请求。
根据 jstack 日志，有 195 个 dubbo 线程从 ScheduledThreadPoolExecutor 中取任务导致处于 WAITING 状态，按理这些 dubbo 线程只负责处理客户端请求，不会处理调度任务，为什么会去调度任务线程中取任务呢？这里暂时抛出这个问题吧，我也不知道答案，希望有大神帮忙解答。
"DubboServerHandler-172.24.16.78:33180-thread-1489" #1636 daemon prio=5 os_prio=0 tid=0x00007f33b0122800 nid=0x48ec waiting on condition [0x00007f32db600000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x0000000089d717a8> (a java.util.concurrent.SynchronousQueue$TransferStack) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:458) at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:362) at java.util.concurrent.SynchronousQueue.take(SynchronousQueue.java:924) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745)
复制代码
这部分 dubbo 线程主要是因为从 ThreadPoolExecutor 取任务来执行时被挂起（309 个线程），这些线程正常处理完第一个请求后，就会回到线程池等待新的请求。由于这里使用 newFixedThreadPool 作为 dubbo 请求处理池，因此每个新请求默认都会创建新线程来处理，除非达到池的限定值。只有达到线程池最大线程数量，新的请求来临才会被加入任务队列，哪些阻塞在 getTask()的线程才会得到复用。
"DubboServerHandler-172.24.16.78:33180-thread-236" #1727 daemon prio=5 os_prio=0 tid=0x00007f336403b000 nid=0x4b8b waiting for monitor entry [0x00007f32d58a4000] java.lang.Thread.State: BLOCKED (on object monitor) at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.checkRollover(RollingFileManager.java:149) - waiting to lock <0x0000000085057998> (a org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager) at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:88) at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:155) at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:128) at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:119) at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84) at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:390) at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:375) at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:359) at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:349) at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63) at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:146) at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:1993) at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1852) at org.apache.logging.slf4j.Log4jLogger.info(Log4jLogger.java:179) at com.alibaba.dubbo.common.logger.slf4j.Slf4jLogger.info(Slf4jLogger.java:42) at com.alibaba.dubbo.common.logger.support.FailsafeLogger.info(FailsafeLogger.java:93) at com.dianwoba.universe.dubbo.filter.ResponseFilter$1.run(ResponseFilter.java:116) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745)
复制代码
waiting for monitor entry ：说明当前线程正处于 EntryList 队列中，等待获取监视器锁。
说明：Java 中 synchronized 的同步语义主要基于 Java 对象头和 monitor 实现，每个 monitor 同一时间只能由一个线程拥有，其他想要获取该 monitor 只能等待，其中 monitor 具有两个队列：WaitSet 和 EntryList。当某个线程在拥有 monitor 时，调用了 Object.wait()，则会释放 monitor，进入 WaitSet 队列等待，此时线程状态为 WAITING，WaitSet 中的等待的状态是 “in Object.wait()”。当其他线程调用 Object 的 notify()/notifyAll()唤醒该线程后，将会重新竞争 monitor；当某个线程尝试进入 synchronized 代码块或方法时，获取 monitor 失败则会进入 EntryList 队列，此时线程状态为 BLOCKED，EntryList 中等待的状态为“waiting for monitor entry”。
根据 jstack 日志，有 377 个 dubbo 线程在等待锁定资源“0x0000000085057998”，从堆栈可知，这些线程都在竞争 RollingRandomAccessFileManager 的 monitor，让我们看看那个线程拥有了该监视器，看日志：
"DubboServerHandler-172.24.16.78:33180-thread-429" #553 daemon prio=5 os_prio=0 tid=0x00007f339c09f800 nid=0x4467 waiting for monitor entry [0x00007f331f53a000] java.lang.Thread.State: BLOCKED (on object monitor) at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.checkRollover(RollingFileManager.java:149) - locked <0x0000000085057998> (a org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager) at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:88) at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:155) at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:128) at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:119) at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84) at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:390) at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:375) at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:359) at org.apache.logging.log4j.core.config.LoggerConfig.logParent(LoggerConfig.java:381) at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:376) at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:359) at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:349) at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63) at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:146) at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:1993) at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1852) at org.apache.logging.slf4j.Log4jLogger.warn(Log4jLogger.java:239) at com.alibaba.dubbo.common.logger.slf4j.Slf4jLogger.warn(Slf4jLogger.java:54) at com.alibaba.dubbo.common.logger.support.FailsafeLogger.warn(FailsafeLogger.java:107) at com.alibaba.dubbo.rpc.filter.TimeoutFilter.invoke(TimeoutFilter.java:48) at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91) at com.alibaba.dubbo.rpc.protocol.dubbo.filter.TraceFilter.invoke(TraceFilter.java:78) at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91) at com.alibaba.dubbo.rpc.filter.ContextFilter.invoke(ContextFilter.java:60) at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91) at com.alibaba.dubbo.rpc.filter.GenericFilter.invoke(GenericFilter.java:112) at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91) at com.alibaba.dubbo.rpc.filter.ClassLoaderFilter.invoke(ClassLoaderFilter.java:38) at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91) at com.alibaba.dubbo.rpc.filter.EchoFilter.invoke(EchoFilter.java:38) at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91) at com.alibaba.dubbo.rpc.protocol.dubbo.DubboProtocol$1.reply(DubboProtocol.java:108) at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.handleRequest(HeaderExchangeHandler.java:84) at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.received(HeaderExchangeHandler.java:170) at com.alibaba.dubbo.remoting.transport.DecodeHandler.received(DecodeHandler.java:52) at com.alibaba.dubbo.remoting.transport.dispatcher.ChannelEventRunnable.run(ChannelEventRunnable.java:82) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745)
复制代码
看到该线程的堆栈就一脸懵 b 了，它已经锁定了资源“0x0000000085057998”，但仍然处于 BLOCKED 状态，是不是有死锁的味道？但是这里不是死锁，最可能的原因是：
到此，仍然没有找到问题的原因，再一次观察资源占用情况，发现当出现问题时，内存占用持续增长，且无下降痕迹，然后找运维 dump 了一份 GC 日志，发现 JVM 一直在做 fullGC，而每次 GC 之后内存基本没变化，说明程序中发生了内存泄漏。最后定位到发生内存泄漏的地方是一个分页查询接口，SQL 语句中漏掉了 limit,offset，够初心大意了。
这尼玛一次性将整张表的数据查出来（300 万），还要对 300 万记录循环处理一遍，这内存不爆掉就怪了。正是因为该原因，导致内存长时间没有释放，JVM 执行 fullGC 无法回收内存，导致持续做 fullGC，CPU 被耗尽，无法处理应用请求。
综上，罪魁祸首是发生了内存泄漏，JVM 一直做 fullGC，导致 CPU 突然飙升，Dubbo 活动线程数增大，锁竞争严重，请求处理超时。根据以上分析，同时也暴露了另外一个不合理的问题：dubbo 线程池数量配置过大，最大值为 1500，也就是说最终线程池中会有 1500 个线程来处理用户请求，当并发量高时，活动线程数增加，CPU 频繁进行上下文切换，系统的吞吐率并不会太高。这是一个优化点。
本文记录该过程，一方面是为了记录曾经踩过的坑，同时提高自己的故障分析和处理能力。当需要问题时，一定不要着急，学会分析问题，一步步找到问题所在。尤其是遇到线上问题时，由于无法调试，一定要在应用中做监控，当出现问题时，一定要结合日志来分析，业务中的问题结合业务日志，性能问题结合内存 dump 日志和线程 dump 日志等等。
本文转载自技术锁话公众号。
原文链接：https://mp.weixin.qq.com/s/-lSiVDfqYrKk_w-xitYBhA
评论