轉：https://mp.weixin.qq.com/s/-lSiVDfqYrKk_w-xitYBhA
背景：新功能開發測試完成后，准備發布上線，當發布完第三台機器時，監控顯示其中一台機器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日志
-
大量dubbo線程處於WAITING狀態，看日志：
"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線程只負責處理客戶端請求，不會處理調度任務，為什么會去調度任務線程中取任務呢？這里暫時拋出這個問題吧，我也不知道答案，希望有大神幫忙解答。
-
還有另外一部分WAITING狀態的線程，看日志：
"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()的線程才會得到復用。
-
此外，還有大量dubbo線程處於BLOCKED狀態，看日志：
"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狀態，是不是有死鎖的味道？但是這里不是死鎖，最可能的原因是：
-
線程沒有獲得運行所需的資源；
-
JVM正在進行fullGC
從這部分日志可知，大部分線程阻塞在打印監控日志的過程中，所以很多請求出現超時。主要原因可能是CPU占用率高，持有鎖的線程處理過程非常慢，導致越來越多的線程在鎖競爭中被阻塞，整體性能下降。
到此，仍然沒有找到問題的原因，再一次觀察資源占用情況，發現當出現問題時，內存占用持續增長，且無下降痕跡，然后找運維dump了一份GC日志，發現JVM一直在做fullGC，而每次GC之后內存基本沒變化，說明程序中發生了內存泄漏。最后定位到發生內存泄漏的地方是一個分頁查詢接口，SQL語句中漏掉了limit,offset，夠初心大意了。
這尼瑪一次性將整張表的數據查出來（300萬），還要對300萬記錄循環處理一遍，這內存不爆掉就怪了。正是因為該原因，導致內存長時間沒有釋放，JVM執行fullGC無法回收內存，導致持續做fullGC，CPU被耗盡，無法處理應用請求。
綜上，罪魁禍首是發生了內存泄漏，JVM一直做fullGC，導致CPU突然飆升，Dubbo活動線程數增大，鎖競爭嚴重，請求處理超時。根據以上分析，同時也暴露了另外一個不合理的問題：dubbo線程池數量配置過大，最大值為1500，也就是說最終線程池中會有1500個線程來處理用戶請求，當並發量高時，活動線程數增加，CPU頻繁進行上下文切換，系統的吞吐率並不會太高。這是一個優化點。
本文記錄該過程，一方面是為了記錄曾經踩過的坑，同時提高自己的故障分析和處理能力。當需要問題時，一定不要着急，學會分析問題，一步步找到問題所在。尤其是遇到線上問題時，由於無法調試，一定要在應用中做監控，當出現問題時，一定要結合日志來分析，業務中的問題結合業務日志，性能問題結合內存dump日志和線程dump日志等等。
歡迎指出本文有誤的地方！