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

是甜甜的脑残粉
2,035 阅读5分钟

最近做链路追踪，然后在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会话中。

image.png

image.png

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

从源码验证

这里我贴一下我们的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这是我们的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的多线程复用问题。

avatar
文章
阅读
粉丝