双十一预热压测过程中,陆陆续续发现了些中间件、工程代码中隐藏的坑,引发内存溢出、cpu消耗过高、线程池不可用...... 按顺序一个个总结下,便于日后问题回顾~
一、故事的开始
叮!叮!叮! 有天突然线上大批量告警,系统超时~
难道“某某云”又出问题了??因为在昨天刚刚遇到“某某云”服务器上DB大量延时,并且后台监控没有任何异样。也就是这个错误的方向导致了故障持续了许久。
看应用监控发现是某些交易耗时严重,也怀疑到是某个节点有问题 (因为并不是所有交易都是超时),挨个看了下链路监控全都是到交易主链路的pfs这个系统开始超时,下游系统监控耗时正常,并且只有其中003这台机器有此现象(耗时情况如下pinpoint截图:),当然 第一反应是赶紧找运维把003这台机器的流量切掉,保存环境现场方便定位具体原因。
二、问题定位过程
跳板机登陆到服务器
top命令,看到有个进程(3043) cpu82.8%
top -Hp 3043查看该进程下子线程占用资源情况
- 其一: 3051这个子线程肯定是关键;
- 其二: 内存信息,堆内存被耗尽基本不可用 (此时差不多可以猜出来是内存泄露触发了FullGC);
jstat -gcutil 3043 1000 5可以看到老年代的对象一直回收不掉,并且FullGC次数一直在增加,就基本确认是内存泄露导致的机器FullGC
通过jstack命令也验证了这个结论
- 把十进制的线程pid转换为jvm中对应的16进制nid:
printf "%x\n” 3051 --> 拿到对应nid: beb - 通过
jstack 3051 | grep beb找到对应的线程堆栈信息,看到“VM Thread”这个线程基本上就是JVM在频繁FullGC
jmap -heap 3043查看jvm中线程运行的情况
线上应用怎么才512内存??(后来才发现之前做网络迁移时候一台老机器配置漏改,也正是这台机器内存分配小,并且当天流量大才触发了线上fullGC,把这个问题暴露了出来)
jmap -dump:live,format=b,file=heap.bin拿到dump文件分析原因
gzip heap.bin压缩后下载到本地分析下;- 分析工具(Jprofiler或者MAT、JConsole),下面是Jprofiler分析截图
搜索整个工程,找到系统中引用的activemq包中的对应代码PooledConnection源码,其中 "connTempQueues"、"connTempTopics"两个类变量刚好跟Jprofiler中分析的关系一致, activemq内部的PooledConnection对象中是存在2个CopyOnWriteArrayList的类型,大概可以定位到是这里的问题导致内存泄露,具体引发的根源看下面具体分析 (摆弄了一堆源码无获,求救)。
apache的论坛上的线索
- apache的论坛上找到一篇关于ActiveMQ内存泄露的issue
issues.apache.org/jira/browse… - apache.issues上也给了具体的代码优化方案(附源码) issues.apache.org/jira/secure…
- activemq的5.6.0版本是存在连接池内存泄露的坑,5.7.0解决了 (确认了下我们系统中刚好是引用了5.6.0的版本),看上面的git源码修复逻辑, pooledconnection实现了session事件监听器接口,在放入监听器时直接将自己放入list中,在创建新的连接前先判断是否已存在该事件监听器,不存在才把监听器add进PooledSession.tempDestEventListeners。而5.6.0这个版本中的activemq在发送消息时候链接池无限创建链接,并且最终在PooledSession的close方法中没有做监听器对象的回收。 直观点看官方解决bug的git提交记录:
Index: src/main/java/org/apache/activemq/pool/PooledConnection.java
===================================================================
--- src/main/java/org/apache/activemq/pool/PooledConnection.java (revision 1378004)
+++ src/main/java/org/apache/activemq/pool/PooledConnection.java (working copy)
@@ -16,6 +16,7 @@
*/
package org.apache.activemq.pool;
+import java.util.List;
import java.util.concurrent.CopyOnWriteArrayList;
import javax.jms.Connection;
@@ -54,13 +55,13 @@
* href="http://jencks.org/Message+Driven+POJOs">this example</a>
*
*/
-public class PooledConnection implements TopicConnection, QueueConnection, EnhancedConnection {
+public class PooledConnection implements TopicConnection, QueueConnection, EnhancedConnection, PooledSessionEventListener {
private static final transient Logger LOG = LoggerFactory.getLogger(PooledConnection.class);
private ConnectionPool pool;
- private boolean stopped;
- private final CopyOnWriteArrayList<TemporaryQueue> connTempQueues = new CopyOnWriteArrayList<TemporaryQueue>();
- private final CopyOnWriteArrayList<TemporaryTopic> connTempTopics = new CopyOnWriteArrayList<TemporaryTopic>();
+ private volatile boolean stopped;
+ private final List<TemporaryQueue> connTempQueues = new CopyOnWriteArrayList<TemporaryQueue>();
+ private final List<TemporaryTopic> connTempTopics = new CopyOnWriteArrayList<TemporaryTopic>();
public PooledConnection(ConnectionPool pool) {
this.pool = pool;
@@ -151,20 +152,17 @@
// Add a temporary destination event listener to the session that notifies us when
// the session creates temporary destinations.
- result.addTempDestEventListener(new PooledSessionEventListener() {
+ result.addTempDestEventListener(this);
+ return (Session) result;
+ }
- @Override
- public void onTemporaryQueueCreate(TemporaryQueue tempQueue) {
- connTempQueues.add(tempQueue);
- }
- @Override
- public void onTemporaryTopicCreate(TemporaryTopic tempTopic) {
- connTempTopics.add(tempTopic);
- }
- });
+ public void onTemporaryQueueCreate(TemporaryQueue tempQueue) {
+ connTempQueues.add(tempQueue);
+ }
- return (Session) result;
+ public void onTemporaryTopicCreate(TemporaryTopic tempTopic) {
+ connTempTopics.add(tempTopic);
}
// EnhancedCollection API
Index: src/main/java/org/apache/activemq/pool/PooledSession.java
===================================================================
--- src/main/java/org/apache/activemq/pool/PooledSession.java (revision 1378004)
+++ src/main/java/org/apache/activemq/pool/PooledSession.java (working copy)
@@ -78,7 +78,10 @@
}
public void addTempDestEventListener(PooledSessionEventListener listener) {
- this.tempDestEventListeners.add(listener);
+ // only add if really needed
+ if (!tempDestEventListeners.contains(listener)) {
+ this.tempDestEventListeners.add(listener);
+ }
}
protected boolean isIgnoreClose() {
@@ -123,6 +126,7 @@
} finally {
consumers.clear();
browsers.clear();
+ tempDestEventListeners.clear();
}
if (invalidate) {
Index: src/main/java/org/apache/activemq/pool/ConnectionPool.java
===================================================================
--- src/main/java/org/apache/activemq/pool/ConnectionPool.java (revision 1378004)
+++ src/main/java/org/apache/activemq/pool/ConnectionPool.java (working copy)
@@ -19,10 +19,10 @@
import java.io.IOException;
import java.util.Iterator;
+import java.util.List;
import java.util.concurrent.ConcurrentHashMap;
-import java.util.concurrent.ConcurrentLinkedQueue;
+import java.util.concurrent.CopyOnWriteArrayList;
import java.util.concurrent.atomic.AtomicBoolean;
-
import javax.jms.JMSException;
import javax.jms.Session;
@@ -39,7 +39,7 @@
private ActiveMQConnection connection;
private ConcurrentHashMap<SessionKey, SessionPool> cache;
- private ConcurrentLinkedQueue<PooledSession> loanedSessions = new ConcurrentLinkedQueue<PooledSession>();
+ private List<PooledSession> loanedSessions = new CopyOnWriteArrayList<PooledSession>();
private AtomicBoolean started = new AtomicBoolean(false);
private int referenceCount;
private ObjectPoolFactory poolFactory;
看了修复的代码大致知道问题的点在哪里了,优先把线上所有引用这个版本ActiveMQ的依赖做了升级,观察后线上没有再重现,并且拉取了线程堆栈文件也都正常,暂时把线程问题处理了,再静下心来学习下埋坑的代码~
三、上源码
我们来从头看下发消息执行的代码 (前面是我们自己封装的发送消息代码)
首先找到业务代码中发送消息的入口:
mqAccssor中调用了jmstemplate模板的send方法
jmstemplate中使用了模版模式,模版方法execute中封装了创建连接和session的逻辑。
继续看execute方法 (跳坑的路口就在这):
其中创建连接是每次都会新建一个实例。 创建session最终调用了前一步创建的连接实例的createSession方法(如下图:),根据jvm堆dump文件分析,查看源码 使用了匿名类,匿名类中隐式的引用了外部类 this$0,所以tempDesEventListeners对pooledConnection有间接的引用。
分析dump文件,引用也在session的tempDestEventListeners这个list中
activemq的修复在session关闭时添加了连接池的清理,在发送完消息之后会调用close方法,同时会清理连接池,之后gc会清理掉不再被引用的连接。
protected boolean isIgnoreClose() {
@@ -123,6 +126,7 @@
} finally {
consumers.clear();
browsers.clear();
+ tempDestEventListeners.clear();
}
在5.7.0版本中的createSession方法也做了拆解
PS: 至于为什么在PooledConnection和ConnectionPool类中把CopyOnWriteArrayList、ConcurrentLinkedQueue类型的成员变量换成了List继续~