Spring WebScoket 多线程问题之源码调试

1,235 阅读5分钟

最近做链路追踪,然后在WebScoket的拦截器里面加了追踪ID,但是发现出现了数据错乱,A用户的信息出现在了B用户的会话里。于是开始解刨一下源码,看看到底问题出在哪里了。

背景

在项目中,我们使用了spring-boot-starter-websocketwebsocket通信服务。在ShakeHandler的实现类的determineUser中读取了用户的身份信息,同时我们创建了一个链路的traceId用作链路追踪,我们把traceId保存在了本地线程(ThreadLocal)中。

然后我们就很自然的在TextWebSocketHandler实现类中随意的使用了ThreadLocal中的traceId做处理。这些例子在afterConnectionEstablished接口、afterConnectionClosed接口、handleMessage接口随处可见。

在测试环境中,同一时间几乎没有并发的情况下,完全看不出来有什么问题,然后最后在没有压测的情况下我们上线了这一功能。

Oh my god!

上线后,很快就出现了数据错乱的情况。比如,A用户的traceId出现在了B用户的请求链路上。因为之前也处理过类似的情况,只不过是Feign相关的多线程问题。没想到在WebSocket上我们又沦陷了。所以,第一反应就是多线程的问题。

立马,我们转到测试环境,开始跑了100的并发,果然问题复现了。

分析

那么,我们开始处理这个多线程问题吧。老规矩,先打印线程ID看看是不是真的复用了线程:

我们分别在afterConnectionEstablishedafterConnectionClosedhandleTextMessage中第一行打印线程日志

 @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会话中。

image.png

image.png

那么,很自然的想到,这应该是tomcat的多线程处理请求产生的。解决办法当然很简单,就是将traceId存放在session.attributes中,因为session内容不会变,然后在每一个websocket事件处理接口时先重置traceIdsession中保存的值,然后再处理业务逻辑。

从源码验证

这里我贴一下我们的jemeter测试脚本。目标是执行一次连接和发一次消息,最后断开,jemeter脚本如下图,使用JMeterWebSocketSamplers-1.2.8.jar插件(安装教程),分别打开一个WebSocket Open Connection + 固定延时 + WebSocket Single Write Sampler + WebSocket Close

image.png

分别说明几个脚本:

  • WebSocket Open Connection 用于开启一个websocket连接
  • 固定延时 延时是为了模拟连接后的消息推送,为了测试线程的复用,可以在这里配置10ms即可,不要超过后面做线程并发时的总时长
  • WebSocket Single Write Sampler 模拟消息推送,connection选择using exists connection image.png
  • 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函数中)查看一下线程堆栈

image.png

可以看到afterConnectionClosed所在的线程(ID=103)实际上来自于http-nio-8840-exec-2这个线程池,那么这个线程池是怎么来的呢?实际上http-nio-xx这是我们的tomcatNioEndpoint维护的线程池。

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是干什么的?NioEndpointtomcat用于处理socket通信的接口类,所有访问tomcat的请求都会由NioEndpoint处理,并启用一个独立线程(来自线程池中的),然后交给不同的RequestHandler处理,最后才会走到我们的afterConnectionClosed等接口上。具体原理可以查询tomcat相关知识,这里不详细介绍了。

这里有一个重点的点,就是tomcat会通过Poller调用AbstractEndpointprocessSocket来处理消息事件,那么我们看一下代码:

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的多线程复用问题。