曹工改bug：cpu狂飆，old gc頻繁，線程神秘死亡連環案件調查報告
前言
前兩天，訪問開發環境上一個java服務，發現一直轉圈圈，因為我開着fiddler，可以看到的現象是，接口一直沒返回；本來想着直接jenkins重新構建一下開發環境（即重啟服務），突然覺得，還是看看到底啥情況吧。
排查過程
登錄到開發環境上（8核16g，centos 7），來了一圈常規操作，結果執行top發現，cpu占用竟然高達400%，然后按照標准流程，那肯定就是查看該進程內占用cpu高的線程是哪個：
top -H -p pid
因為當時沒截圖，只保存了文本：
線程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，調用如下語句，轉成了十六進制
printf "%x\n" 線程id
得到如下結果：
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一直很穩定，看來新生代沒啥問題。
再看看老年代：
jstat -gcold -h 5 19083 1000 2000
可以發現，FGC挺凶殘，再看看OC（old capacity），表示老年代為340m左右（開發環境，沒調參數，都是默認的），再看看OU（old used），都用了340m了，然后每次回收，OU都還是維持在那個程度，說明回收沒啥效果，這些OU里的對象，基本都回收不掉。
回收不掉，那只能看看都是些什么對象了，如果這些對象確實需要，那就說明我們的old區太小；如果不需要這些對象，說明是內存泄漏。
ok，jmap走一波。
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中的類。
我們看看這個類的源碼：
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了。該字段定義如下：
private MessageQueue m_queue = new DefaultMessageQueue(SIZE);其類型為DefaultMessageQueue，我們可以看看這個類的代碼：
public class DefaultMessageQueue implements MessageQueue { private BlockingQueue<MessageTree> m_queue; public DefaultMessageQueue(int size) { m_queue = new ArrayBlockingQueue<MessageTree>(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客戶端源碼，發現這個線程的邏輯，大概如下：
com.dianping.cat.message.io.TcpSocketSender#run
@Override
public void run() {
m_active = true;
while (m_active) {
processAtomicMessage();
// 1
processNormalMessage();
}
}
繼續看1處：
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處方法的實現：
ChannelFuture channel = m_channelManager.channel();
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，繼續看之前那個方法
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處
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。
"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呢，這個還需要分析。
接上文，
public static class ChannelHolder {
// 1
private ChannelFuture m_activeFuture;
private int m_activeIndex = -1;
private String m_activeServerConfig;
private List<InetSocketAddress> m_serverAddresses;
private String m_ip;
private boolean m_connectChanged;
我們現在知道，1處的m_activeFuture是null，這是目前知道的最深入的原因，至於為啥為null？不知道。
我們在代碼里，find usage，查看什么地方會設置這個值。
兩處，1處進行重連，1處進行初始化。
本地復現：初始化
我們在本地進行了嘗試，先試了初始化的場景，我們先關閉了cat服務端，然后在本地復現。
public ChannelManager(Logger logger, List<InetSocketAddress> 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。
但是，一般都不會做的這么挫，都會定時去重連的。那我們看看，難道是重連的代碼有問題嗎？
重連場景分析
com.dianping.cat.message.io.ChannelManager#reconnectDefaultServer
private void reconnectDefaultServer(ChannelFuture activeFuture, List<InetSocketAddress> 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中，好像沒看到這么個線程啊？難道眼花了嗎？
不，眼沒花
[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點多，我們因此反向查看日志。看到了如下部分
[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試了下，看看打日志到底怎么打的
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]部分：
private String getCallerClassName() {
StackTraceElement[] elements = new Exception().getStackTrace();
if (elements.length > 5) {
String className = elements[5].getClassName();
int pos = className.lastIndexOf('.');
if (pos > 0) {
return className.substring(pos + 1);
} else {
return className;
}
}
return "N/A";
}
總之呢，這里就是獲取logger對應的class名稱。
那這么說來，有下面那幾行日志，但是具體是哪個線程打印的，其實也不是很確定了。
[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 06:34:34.862] [ERROR] [ChannelManager] GC overhead limit exceeded
java.lang.OutOfMemoryError: GC overhead limit exceeded
...
[08-20 06:40:28.962] [ERROR] [CatClientModule$CatThreadListener] Uncaught exception thrown out of thread(cat-TcpSocketSender-ChannelManager)
java.lang.OutOfMemoryError: GC overhead limit exceeded
[08-20 06:40:35.337] [ERROR] [CatClientModule$CatThreadListener] Uncaught exception thrown out of thread(cat-3)
java.lang.OutOfMemoryError: GC overhead limit exceeded
原來啊，這幾個線程死了，是因為oom。
線程死了，為啥還記錄了日志了？那是因為美團在new線程的時候，設置了uncaughtExceptionHandler.
java.lang.Thread
public class Thread implements Runnable {
private volatile UncaughtExceptionHandler uncaughtExceptionHandler;
com.dianping.cat.util.Threads.RunnableThread
static class RunnableThread extends Thread {
private static ThreadLocal<String> m_callerThreadLocal = new ThreadLocal<String>();
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。
而最終設置進去的，就是下面這個實現類：
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，就是記錄線程死亡日志。
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。
謝謝大家。