現象

排查思路
另一台服務器CPU正常,由於消息中心有部分老接口是域名調用的,網關已做負載均衡,並且pinpoint上的兩台服務器gc如圖,初步猜測是否是負載不均衡導致。


經運維調試nginx權重無效,證明與負載均衡無關。那么先看子線程,這種情況必定由某幾個線程引起
ps -mp pid -o THREAD,tid,time命令查看子線程,如圖

這個數據上,分兩部分看,1、有3個占用高的線程,2、執行時間可以注意到分別是4天,1天,23小時。說明線程出於某種情況,死鎖,死循環。
由於這時候jstack操作可能引起內存溢出,應用直接掛掉,由運維操作下載日志。
jstack pid |grep tid
由上述子線程pid轉化十六進制查詢對應日志。如下:
"HttpClient@440f33e8-124521" #124521 prio=5 os_prio=0 tid=0x00007f2c7c042800 nid=0x1c4a runnable [0x00007f2c5e9c1000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.EPollArrayWrapper.interrupt(Native Method)
at sun.nio.ch.EPollArrayWrapper.interrupt(EPollArrayWrapper.
java:317)
at sun.nio.ch.EPollSelectorImpl.wakeup(EPollSelectorImpl.
java:207)
- locked <0x000000008658afa0> (a java.lang.Object)
at java.nio.channels.spi.AbstractSelector$1.interrupt(AbstractSelector.
java:213)
at java.nio.channels.spi.AbstractSelector.begin(AbstractSelector.
java:219)
at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:92)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
- locked <0x0000000086587170> (a sun.nio.ch.Util$2)
- locked <0x000000008658ad40> (a java.util.Collections$UnmodifiableSet)
- locked <0x000000008658ab98> (a sun.nio.ch.EPollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.
java:101)
at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.select(ManagedSelector.
java:385)
at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.
java:326)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.
java:342)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.
java:189)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.
java:175)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.
java:139)
at org.eclipse.jetty.io.ManagedSelector$$Lambda$106/586427179.run(Unknown Source)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.
java:754)
at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.
java:672)
at java.lang.Thread.run(Thread.
java:745)
可以看到由多個locked操作,可以看到有引用org.eclipse.jetty.io及sun.nio.ch.,但是我們的代碼里並沒有用到這兩個jar包內容。
代碼內maven引用反推,可以看到jetty包是由定時任務xxl-job引入的,那么可以判斷這個問題是由xxl-job引起的,但是這么多應用都在使用定時任務,為什么只有消息中心有問題?這里拋出這個問題。
查看定時任務的設置,在定時任務配置方向和其他應用有什么不同。
如下可以看到消息中心一共配了17個任務,而其他應用任務最多不超過4個。並且由上面jstack日志所示,有使用到NIO的異步線程EPoll,難道是因為線程池耗盡了,出於某種原因導致死鎖?
那么看下NIO有什么坑吧。下面是我查到的官方原文:
簡單來說,就是epoll這個異步線程是一個復用型線程,他的使用過程是socket協議——開啟通道——執行——關閉通道——socket協議關閉,
但是本來應該被移除的fd,被后來的線程給注冊上了,導致這個線程進入死循環。這也可以解釋為什么只有3個線程死鎖,並沒有出現大面積死鎖,因為這是一個並發導致的隱藏問題。
然后再看這三個子線程,按當時時間反推,毛估估剛好是整點觸發,猜測是不是由於17個定時任務,在某個時間同時觸發導致這個問題?這個沒有證據能夠證明他是這個原因導致的。
但是在看源碼的時候可以注意到,jetty里有一個httpclient有使用到epoll的異步線程,剛好這也是消息中心的定時任務與其他應用的不同之處。
由於.net應用沒有定時任務,即通過xxl-job的GLUE方式使用jetty的httpclient基於消息中心服務器請求接口。
那么可以大概斷定,大概率是這里導致的死鎖,去xxl-job的github上也可以看到作者將這種方式改成了java.net.HttpURLConnection方式請求。改完配置,重新發布,已觀察兩天沒有問題。后續若再發現類似問題,繼續跟進
