曹工改bug：cpu狂飆，old gc頻繁，執行緒神祕死亡連環案件調查報告
阿新 • • 發佈：2020-08-25
# 曹工改bug：cpu狂飆，old gc頻繁，執行緒神祕死亡連環案件調查報告
# 前言
前兩天，訪問開發環境上一個java服務，發現一直轉圈圈，因為我開著fiddler，可以看到的現象是，介面一直沒返回；本來想著直接jenkins重新構建一下開發環境（即重啟服務），突然覺得，還是看看到底啥情況吧。
#排查過程
登入到開發環境上（8核16g，centos 7），來了一圈常規操作，結果執行top發現，cpu佔用竟然高達400%，然後按照標準流程，那肯定就是檢視該程序內佔用cpu高的執行緒是哪個：
```shell
top -H -p pid
```
因為當時沒截圖，只儲存了文字：
```shell
執行緒id cpu佔用率
19093 root 20 0 6599852 1.107g 14612 S 19.3 7.1 30:17.26 java
19087 root 20 0 6599852 1.107g 14612 S 15.3 7.1 22:28.15 java
19089 root 20 0 6599852 1.107g 14612 S 15.3 7.1 22:28.99 java
19091 root 20 0 6599852 1.107g 14612 S 15.3 7.1 22:27.07 java
19092 root 20 0 6599852 1.107g 14612 S 15.3 7.1 22:27.47 java
19085 root 20 0 6599852 1.107g 14612 S 14.3 7.1 22:28.11 java
19086 root 20 0 6599852 1.107g 14612 S 14.3 7.1 22:27.32 java
19088 root 20 0 6599852 1.107g 14612 S 14.3 7.1 22:27.11 java
19090 root 20 0 6599852 1.107g 14612 S 13.6 7.1 22:30.03 java
```
最左側是執行緒id，後面有一列為cpu佔用率，可以發現，一個執行緒就佔用了20%的cpu。
然後手動將這幾個執行緒id，呼叫如下語句，轉成了十六進位制
```shell
printf "%x\n" 執行緒id
```
得到如下結果：
```shell
hex 執行緒id
4a95 19093
4a94 19092
4a90 19088
4a8d 19085
4a8f 19087
4a91 19089
4a92 19090
4a8e 19086
4a93 19091
```
然後執行jstack，檢視這幾個執行緒id，發現都是些gc執行緒。
既然問題出在gc這裡，那自然要祭出jstat神器了。
先看看新生代，倒數第二列，YGC一直很穩定，看來新生代沒啥問題。
再看看老年代：
```shell
jstat -gcold -h 5 19083 1000 2000
```
可以發現，FGC挺凶殘，再看看OC（old capacity），表示老年代為340m左右（開發環境，沒調引數，都是預設的），再看看OU（old used），都用了340m了，然後每次回收，OU都還是維持在那個程度，說明回收沒啥效果，這些OU裡的物件，基本都回收不掉。
回收不掉，那隻能看看都是些什麼物件了，如果這些物件確實需要，那就說明我們的old區太小；如果不需要這些物件，說明是記憶體洩漏。
ok，jmap走一波。
```shell
jmap -dump:live,format=b,file=19083.hprof 19083
```
拿到對應的檔案後，下載到本地，用MAT（Eclipse Memory Analyzer ）進行分析。
開啟檔案的時候，就會讓你選擇，是否檢測記憶體洩漏，我們這裡大概率是記憶體洩漏，那就讓MAT幫我們分析一波。
# MAT分析記憶體洩漏
仔細看上圖，可以發現，
* 執行緒一般是作為一個gc root，這裡的執行緒名稱是，cat-TcpSocketSender，執行緒的class型別是：
`org.unidal.helper.Threads$RunnableThread`
這個類是因為我們這邊引入了美團的cat作為監控元件，這個監控元件，有一個服務端war包，部署在tomcat中，監聽2280埠；有一個客戶端jar包，我們的應用裡，就引入了這個jar。所以，這個類，就是美團客戶端jar中的類。
我們看看這個類的原始碼：
```java
org.unidal.helper.Threads.RunnableThread
static class RunnableThread extends Thread {
private Runnable m_target;
```
發現其繼承了jdk的Thread。
這個類中的m_target，指向了`com.dianping.cat.message.io.TcpSocketSender`這個類。
* `com.dianping.cat.message.io.TcpSocketSender`這個類中，有一個欄位，叫m_queue，其Retained Heap達到了400m，也就是說，m_queue裡引用的物件，全部加起來，已經是400m了。
該欄位定義如下：
```java
private MessageQueue m_queue = new DefaultMessageQueue(SIZE);
```
其型別為DefaultMessageQueue，我們可以看看這個類的程式碼：
```java
public class DefaultMessageQueue implements MessageQueue {
private BlockingQueue m_queue;
public DefaultMessageQueue(int size) {
m_queue = new ArrayBlockingQueue(size);
}
```
很簡單，就是維護了一個佇列，名稱也叫m_queue，補充一下，這裡的size，傳進來的是5000.
然後構造了一個ArrayBlockingQueue，裡面存放的每個item的class型別，就是MessageTree。
到此為止，大概知道，是美團的cat客戶端jar包中，一個佇列裡存了大量資料，大概有400m，幾乎把old 區佔用完了，而且一直gc不掉。
現在就看一下，這裡面存放的是什麼東西？
如果圖小，可在單獨tab檢視，這裡可以看到，arrayBlockingQueue的陣列中，存放了5000個物件，5000就是這個佇列的size的大小。
那具體每個item裡存什麼了呢？
這個類中，有metric，heartbeats，transaction，event這些，這都是要上報到cat服務端的監控資料；而下面的m_ipaddress這些，正好是我們服務端的ip地址。
大概可以猜出來，這個item，存放了要上報到cat服務端的資料。
那麼，問題變成了，為什麼沒有上報呢？因為我們這邊前一陣服務端斷了一次電，大概猜到是因為cat服務端沒有啟動，在伺服器上一看，確實沒啟動。
所以，問題大概就是：因為服務端沒啟動，所以這邊一直髮送不出去，導致積壓在這個佇列裡。
我們進一步查看了對應的cat客戶端原始碼，發現這個執行緒的邏輯，大概如下：
```java
com.dianping.cat.message.io.TcpSocketSender#run
@Override
public void run() {
m_active = true;
while (m_active) {
processAtomicMessage();
// 1
processNormalMessage();
}
}
```
繼續看1處：
```java
private void processNormalMessage() {
while (true) {
// 1
ChannelFuture channel = m_channelManager.channel();
// 2
if (channel != null) {
try {
// 3
MessageTree tree = m_queue.poll();
if (tree != null) {
// 4
sendInternal(channel, tree);
tree.setMessage(null);
} else {
try {
Thread.sleep(5);
} catch (Exception e) {
m_active = false;
}
break;
}
} catch (Throwable t) {
m_logger.error("Error when sending message over TCP socket!", t);
}
} else {
// 5
try {
Thread.sleep(5);
} catch (Exception e) {
m_active = false;
}
}
}
}
```
* 1處，從m_channelManager,獲取一個channel，因為cat客戶端使用了netty，所以這裡是要獲取一個netty的channle，用來發送資料
* 2處，如果拿到的channel不為null，則進入3處；否則進入5處
* 3處，從我們前面提到的罪魁禍首的佇列中，取1個item，這裡的item就是MessageTree
* 4處，使用channel傳送對應的tree
* 5處，如果拿到的channel是null，則睡眠5s
根據上面的邏輯，為什麼沒有從佇列裡取item去傳送呢，推測是因為在上面1處時，拿到的channel是null。
但是口說無憑，怎麼證實呢，我們得先看看1處方法的實現：
```java
ChannelFuture channel = m_channelManager.channel();
```
```java
com.dianping.cat.message.io.ChannelManager#channel
public ChannelFuture channel() {
// 1
if (m_activeChannelHolder != null) {
ChannelFuture future = m_activeChannelHolder.getActiveFuture();
if (checkWritable(future)) {
return future;
}
}
// 2
return null;
}
```
如果1處，這裡的m_activeChannelHolder是null，那麼自然會返回null，那我們看看是不是null吧，還是使用mat，通過TcpSocketSender物件，找到m_channelManager。
然後再去檢視m_channelManager的屬性：
但是我們發現，這個屬性並不是null。
ok，繼續看之前那個方法
```java
public ChannelFuture channel() {
// 1
if (m_activeChannelHolder != null) {
// 2
ChannelFuture future = m_activeChannelHolder.getActiveFuture();
if (checkWritable(future)) {
return future;
}
}
return null;
}
```
現在證實，1處的m_activeChannelHolder不為null，那麼，就會走到2處
```java
com.dianping.cat.message.io.ChannelManager.ChannelHolder#getActiveFuture
public ChannelFuture getActiveFuture() {
return m_activeFuture;
}
```
那我們繼續看看m_activeChannelHolder這個物件裡的m_activeFuture欄位吧：
好，這裡發現，m_activeFuture是null。
繼續深入checkWritable方法：
大家仔細看上面幾張圖，checkWritable會返回false，因此channel方法會返回null。
為什麼積壓發不出去的問題，已經清楚了，是因為channel總是空的。
而在jstack檔案中，也能看到，每次jstack的結果，都是這個執行緒在sleep。
```shell
"cat-TcpSocketSender" #116 daemon prio=5 os_prio=0 tid=0x00007f2d6066b000 nid=0x4ce5 sleeping[0x00007f2df9b32000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at com.dianping.cat.message.io.TcpSocketSender.processNormalMessage(TcpSocketSender.java:226)
at com.dianping.cat.message.io.TcpSocketSender.run(TcpSocketSender.java:240)
at java.lang.Thread.run(Thread.java:748)
at org.unidal.helper.Threads$RunnableThread.run(Threads.java:294)
```
# 繼續深入
到此為止，我們知道了表面上的原因了，是因為TcpSocketSender拿不到channel；那為啥拿不到channel呢，這個還需要分析。
接上文，
```java
public static class ChannelHolder {
// 1
private ChannelFuture m_activeFuture;
private int m_activeIndex = -1;
private String m_activeServerConfig;
private List m_serverAddresses;
private String m_ip;
private boolean m_connectChanged;
```
我們現在知道，1處的m_activeFuture是null，這是目前知道的最深入的原因，至於為啥為null？不知道。
我們在程式碼裡，find usage，檢視什麼地方會設定這個值。
兩處，1處進行重連，1處進行初始化。
##本地復現：初始化
我們在本地進行了嘗試，先試了初始化的場景，我們先關閉了cat服務端，然後在本地復現。
```java
public ChannelManager(Logger logger, List serverAddresses, ClientConfigManager configManager,MessageIdFactory idFactory) {
...
if (StringUtils.isNotEmpty(routerConfig)) {
...
} else {
// 1
ChannelHolder holder = initChannel(serverAddresses, null);
// 2
if (holder != null) {
m_activeChannelHolder = holder;
} else {
// 3
m_activeChannelHolder = new ChannelHolder();
m_activeChannelHolder.setServerAddresses(serverAddresses);
m_logger.error("error when init cat module due to error config xml in client.xml");
}
}
}
```
* 1處，初始化channel，因為服務端是關了的，不成功，這裡返回null，因此holder為null
* 2處，holder不為null，我們這裡走不到
* 3處，我們進入這裡，這裡直接new了一個ChannelHolder，然後new了之後，也沒設定什麼屬性，因此，這裡m_activeChannelHolder裡面的m_activeFuture欄位，就是null。
ok，我們現在知道了，如果啟動的時候，cat服務端不可用，會導致m_activeFuture為null。
但是，一般都不會做的這麼挫，都會定時去重連的。那我們看看，難道是重連的程式碼有問題嗎？
## 重連場景分析
```java
com.dianping.cat.message.io.ChannelManager#reconnectDefaultServer
private void reconnectDefaultServer(ChannelFuture activeFuture, List serverAddresses) {
try {
int reconnectServers = m_activeChannelHolder.getActiveIndex();
if (reconnectServers == -1) {
reconnectServers = serverAddresses.size();
}
for (int i = 0; i < reconnectServers; i++) {
// 1
ChannelFuture future = createChannel(serverAddresses.get(i));
// 1.1
if (future != null) {
ChannelFuture lastFuture = activeFuture;
// 2
m_activeChannelHolder.setActiveFuture(future);
m_activeChannelHolder.setActiveIndex(i);
closeChannel(lastFuture);
break;
}
}
} catch (Throwable e) {
m_logger.error(e.getMessage(), e);
}
}
```
1處，進行了重連；
2處，將channel設定到future，因為1.1處進行了判斷，future不為null，才走到2，說明如果走到2處，future肯定不為null。
那我們有理由懷疑，這個方法難道沒有執行到？
我們在這裡打了斷點，本地除錯的時候，發現確實進來了這個方法。
但是，比較奇怪的是，這個重連邏輯，是有一個單獨的執行緒，名字叫`cat-TcpSocketSender-ChannelManager`
但是，更奇怪的是，我之前在jstack中，好像沒看到這麼個執行緒啊？難道眼花了嗎？
不，眼沒花
```shell
[root@localhost ~]# grep cat-TcpSocketSender-ChannelManager 19083.txt
[root@localhost ~]# grep cat- 19083.txt
"cat-TcpSocketSender" #116 daemon prio=5 os_prio=0 tid=0x00007f2d6066b000 nid=0x4ce5 sleeping[0x00007f2df9b32000]
```
可以看到，我們的jstack檔案裡，真的沒有這個執行緒。
好了，我懷疑，它死了。
可以看到，本地正常情況下，竟然有4個cat執行緒，而伺服器上，只有1個。
# 執行緒神祕死亡之謎
有點意思，執行緒都死了，這下就不好排查了，因為只要有一個未捕獲異常，就會導致執行緒掛掉。
那麼多程式碼，怎麼知道哪裡出了異常呢？
日誌。
我們查了下日誌，找到了日誌檔案。
當時排查時間，大概是上午11點多，我們因此反向檢視日誌。看到了如下部分
```java
[08-20 10:27:36.749] [INFO] [ChannelManager] start connect server/10.15.9.113:2280
[08-20 10:27:36.752] [INFO] [ChannelManager] Connected to CAT server at /10.15.9.113:2280
[08-20 10:27:46.764] [INFO] [ChannelManager] router config changed :10.15.9.113:2280;
[08-20 10:27:46.764] [INFO] [ChannelManager] start connect server/10.15.9.113:2280
[08-20 10:27:46.768] [INFO] [ChannelManager] Connected to CAT server at /10.15.9.113:2280
[08-20 10:27:46.768] [INFO] [ChannelManager] success when init CAT server, new active holderactive future :/10.15.9.113:2280 index:0 ip:10.15.9.113 server config:10.15.9.113:2280;
[08-20 10:27:46.768] [INFO] [ChannelManager] close channel /10.15.9.113:2280
[08-20 10:27:46.769] [INFO] [ChannelManager] switch active channel to active future :/10.15.9.113:2280 index:0 ip:10.15.9.113 server config:10.15.9.113:2280;
```
其實我們對cat的日誌也不熟悉，不知道中間那個[ChannelManager]是什麼意思，以為是執行緒名稱，當時就很疑惑，這些日誌說明了，10點27分的時候，這個執行緒還活著啊，為啥就死了呢？
但我們不確定那個[]中間就是執行緒名，而且感覺也不是很像執行緒名稱。
後面又本地debug試了下，看看打日誌到底怎麼打的
```java
org.unidal.lookup.logger.TimedConsoleLogger#getTimedMessage
private String getTimedMessage(String level, String message) {
if (m_showClass) {
// 1
return m_format.format(new Object[] { new Date(), level, message, getCallerClassName() });
} else {
return m_format.format(new Object[] { new Date(), level, message });
}
}
```
發現進入了1處的getCallerClassName，這個返回的值，就被作為了前面提到的[ChannelManager]部分：
```java
private String getCallerClassName() {
StackTraceElement[] elements = new Exception().getStackTrace();
if (elements.length > m_callerThreadLocal = new ThreadLocal();
private Runnable m_target;
private String m_caller;
public RunnableThread(ThreadGroup threadGroup, Runnable target, String name, UncaughtExceptionHandler handler) {
super(threadGroup, target, name);
m_target = target;
m_caller = getCaller();
setDaemon(true);
// 1
setUncaughtExceptionHandler(handler);
if (getPriority() != Thread.NORM_PRIORITY) {
setPriority(Thread.NORM_PRIORITY);
}
}
```
上面1處可以看到，在new執行緒的時候，會手動設定UncaughtExceptionHandler。
而最終設定進去的，就是下面這個實現類：
```java
static class Manager implements UncaughtExceptionHandler {
....
@Override
public void uncaughtException(Thread thread, Throwable e) {
for (ThreadListener listener : m_listeners) {
// 1
boolean handled = listener.onUncaughtException(thread, e);
if (handled) {
break;
}
}
}
}
```
當執行緒發生了未捕獲異常時，就會進到1這裡，通知listener。
其中一個listener，就是記錄執行緒死亡日誌。
```java
public static final class CatThreadListener extends AbstractThreadListener {
private final ModuleContext m_ctx;
private CatThreadListener(ModuleContext ctx) {
m_ctx = ctx;
}
...
@Override
public boolean onUncaughtException(Thread thread, Throwable e) {
m_ctx.error(String.format("Uncaught exception thrown out of thread(%s)", thread.getName()), e);
return true;
}
}
```
# 總結
至此，本探的案子就算是破了，也算是一個連環案了，是不是還有點意思呢？cpu飆高的背後是gc，gc的背後是記憶體洩漏，記憶體洩漏的背後，是cat服務端沒起。
而啟動cat服務端後，狀態並沒有好轉，這背後竟然又是因為執行緒神祕死亡，神祕死亡的原因，結果是oom。
it is a circle。
謝謝