最近做链路追踪,然后在WebScoket
的拦截器里面加了追踪ID,但是发现出现了数据错乱,A用户的信息出现在了B用户的会话里。于是开始解刨一下源码,看看到底问题出在哪里了。
背景
在项目中,我们使用了spring-boot-starter-websocket
做websocket
通信服务。在ShakeHandler
的实现类的determineUser
中读取了用户的身份信息,同时我们创建了一个链路的traceId
用作链路追踪,我们把traceId
保存在了本地线程(ThreadLocal
)中。
然后我们就很自然的在TextWebSocketHandler
实现类中随意的使用了ThreadLocal
中的traceId
做处理。这些例子在afterConnectionEstablished
接口、afterConnectionClosed
接口、handleMessage
接口随处可见。
在测试环境中,同一时间几乎没有并发的情况下,完全看不出来有什么问题,然后最后在没有压测的情况下我们上线了这一功能。
Oh my god!
上线后,很快就出现了数据错乱的情况。比如,A用户的traceId
出现在了B用户的请求链路上。因为之前也处理过类似的情况,只不过是Feign
相关的多线程问题。没想到在WebSocket
上我们又沦陷了。所以,第一反应就是多线程的问题。
立马,我们转到测试环境,开始跑了100的并发,果然问题复现了。
分析
那么,我们开始处理这个多线程问题吧。老规矩,先打印线程ID看看是不是真的复用了线程:
我们分别在afterConnectionEstablished
、afterConnectionClosed
、handleTextMessage
中第一行打印线程日志
@Override
public void afterConnectionEstablished(WebSocketSession session) throws Exception {
log.info(
"Thead afterConnectionEstablished {} -> {}",
session.getId(),
Thread.currentThread().getId());
}
@Override
public void afterConnectionClosed(WebSocketSession session, CloseStatus status) throws Exception {
log.info(
"Thead afterConnectionClosed {} -> {}", session.getId(), Thread.currentThread().getId());
}
@Override
protected void handleTextMessage(WebSocketSession session, TextMessage message) {
log.info("Thead handleTextMessage {} -> {}", session.getId(), Thread.currentThread().getId());
}
然后用jemeter
跑压测脚本,果然出现了同一个线程ID(103)在多次出现,而且还出现了不同的session
会话中。
那么,很自然的想到,这应该是tomcat
的多线程处理请求产生的。解决办法当然很简单,就是将traceId
存放在session.attributes
中,因为session
内容不会变,然后在每一个websocket
事件处理接口时先重置traceId
为session
中保存的值,然后再处理业务逻辑。
从源码验证
这里我贴一下我们的jemeter
测试脚本。目标是执行一次连接和发一次消息,最后断开,jemeter
脚本如下图,使用JMeterWebSocketSamplers-1.2.8.jar
插件(安装教程),分别打开一个WebSocket Open Connection
+ 固定延时 + WebSocket Single Write Sampler
+ WebSocket Close
:
分别说明几个脚本:
WebSocket Open Connection
用于开启一个websocket连接固定延时
延时是为了模拟连接后的消息推送,为了测试线程的复用,可以在这里配置10ms
即可,不要超过后面做线程并发时的总时长WebSocket Single Write Sampler
模拟消息推送,connection
选择using exists connection
WebSocket Close
断开websocket
连接
配置好了测试脚本,立即以程数=1
执行,后台输出日志:
INFO c.f.l.w.h.a.AppBaseMessageHandler Thead afterConnectionEstablished fca7eba3-c5e2-a05e-73ed-08d144a021a9 -> 100
INFO c.f.l.w.h.a.AppBaseMessageHandler Thead handleTextMessage fca7eba3-c5e2-a05e-73ed-08d144a021a9 -> 104
INFO c.f.l.w.h.a.AppBaseMessageHandler Thead afterConnectionClosed fca7eba3-c5e2-a05e-73ed-08d144a021a9 -> 103
可以看到,在连接、发送消息、断开连接这三个处理,后台使用了三个不同的线程。
那么线程来自哪儿,我们断点(例如断点放在afterConnectionClosed
函数中)查看一下线程堆栈
可以看到afterConnectionClosed
所在的线程(ID=103)实际上来自于http-nio-8840-exec-2
这个线程池,那么这个线程池是怎么来的呢?实际上http-nio-xx
这是我们的tomcat
的NioEndpoint
维护的线程池。
class NioEndpoint extends AbstractJsseEndpoint<NioChannel,SocketChannel> {
@Override
public void startInternal() throws Exception {
if (!running) {
running = true;
paused = false;
...
// Create worker collection
if (getExecutor() == null) {
createExecutor(); // 这里创建了线程池
}
...
}
}
...
}
class AbstractEndpoint {
// 我们再来看一下创建这个线程池的实现:
public void createExecutor() {
internalExecutor = true;
TaskQueue taskqueue = new TaskQueue();
TaskThreadFactory tf = new TaskThreadFactory(getName() + "-exec-", daemon, getThreadPriority());
executor = new ThreadPoolExecutor(getMinSpareThreads(), getMaxThreads(), 60, TimeUnit.SECONDS,taskqueue, tf); // 这里就是我们进入`afterConnectionClosed`的线程来源
taskqueue.setParent( (ThreadPoolExecutor) executor);
}
}
NioEndpoint
是干什么的?NioEndpoint
是tomcat
用于处理socket
通信的接口类,所有访问tomcat
的请求都会由NioEndpoint
处理,并启用一个独立线程(来自线程池中的),然后交给不同的RequestHandler
处理,最后才会走到我们的afterConnectionClosed
等接口上。具体原理可以查询tomcat
相关知识,这里不详细介绍了。
这里有一个重点的点,就是tomcat
会通过Poller
调用AbstractEndpoint
的processSocket
来处理消息事件,那么我们看一下代码:
public boolean processSocket(SocketWrapperBase<S> socketWrapper,
SocketEvent event, boolean dispatch) {
try {
if (socketWrapper == null) {
return false;
}
SocketProcessorBase<S> sc = null; // Runnable执行单元,也就是我们的worker
if (processorCache != null) {
sc = processorCache.pop();
}
if (sc == null) {
sc = createSocketProcessor(socketWrapper, event); // 没有worker缓存,新建一个worker
} else {
sc.reset(socketWrapper, event); // 重置worker的相关信息!!!
}
Executor executor = getExecutor();
if (dispatch && executor != null) {
executor.execute(sc); // 调用线程池执行worker的run方法
} else {
sc.run();
}
} catch (RejectedExecutionException ree) {
getLog().warn(sm.getString("endpoint.executor.fail", socketWrapper) , ree);
return false;
} catch (Throwable t) {
ExceptionUtils.handleThrowable(t);
// This means we got an OOM or similar creating a thread, or that
// the pool and its queue are full
getLog().error(sm.getString("endpoint.process.fail"), t);
return false;
}
return true;
}
所以,从源码上看,我们很清楚的知道,最终处理我们的websocket
的线程在线程池中可能是会复用的,也就是我们的SocketProcessorBase
工作单元,只是每次执行任务时都会重置socket
相关信息。
那么,如果我们在可能被复用的线程(也就是coreThreads
)上保存了一些个线程信息(放在ThreadLocal
中),如果不做好及时重置,就会出现数据错乱的现象了。
归根到底还是在使用本地线程变量的时候没有重点考虑tomcat
的多线程复用问题。