一个线程阻塞引起的超时问题

背景

最近在测试一个线上的服务时，发现一个诡异的现象，服务在接收到用户的请求后经过一系列逻辑处理后，将结果返回客户端会耗费4到5秒的延迟。这是无法忍受的时间，那为什么在应答给客户端的时候需要这么长时间呢？ 测试发现，单次请求第三方的逻辑，不会出现这种问题，流程如下所示：

而对于在两次调用第三方接口的逻辑，才会出现这种问题，流程如下所示：

排查

服务端使用的netty框架开发，客户端与服务端这段通信走的是PB协议，服务端与第三方通信直接调用的http接口，也是使用netty自己实现了一个httplient。延迟发生在客户端与服务端之间，所以最先想到的是不是有异常大的包，但是抓包看到也就只有500个字节，即使是公网也是毫秒级别搞定的事，问题不在这；接着开始怀疑负责服务端与客户端处理的线程阻塞了，但是仅仅从debug代码去分析，没办法定位问题，在分析着eventloop执行的动作时也没有找到非常耗时的任务，所以这个点在无法定位的情况下，只能暂时先搁置了，转去怀疑发送消息的逻辑是不是有问题呢？看下发送的逻辑

hannel.writeAndFlush(encryptMsg).addListener(new ChannelFutureListener() {
                        @Override
                        public void operationComplete(ChannelFuture future) throws Exception {
                            logger.info("serial no : {} back to clinet", clientSerialNo);
                            // 监控
                            MonitorRecorder.recordMessageBackend(transactionDto.getJnlNo());
                        }
                    });

很简单的一段代码，使用当前线程直接发送，发送完成之后打印一段日志。这个时候考虑到一个问题，netty在处理一个channel的逻辑的时候，是一个线程全权处理的，进入writeAndFlush方法也可以发现，在发送的时候会有一个判断，这段代码很是经典，如下图所示：

如果调用writeAndFlush方法不是channel绑定的线程，那么启动一个任务，在执行这个任务的时候就是绑定到channel上的线程去执行writeAndFlush方法了，所以再回到问题上，对于一个channel来说，如果它绑定的线程阻塞了，那它后续的动作都会阻塞。那会不会是因为服务端在调用第三方的接口时阻塞掉了呢？再来看下这段发送的代码：

private static void connect(final RequestRoot msg, final UserLogin userHead) throws Exception {
        Bootstrap b = getBoot();
        b.handler(new PfyhClientInitializer(new PfyhClientHandler(msg, userHead)));
        // Start the client.
        ChannelFuture f = b.connect(GlobalConstants.PFYH_TRADE_SERVER, GlobalConstants.PFYH_TRADE_PORT).sync();
        f.channel().closeFuture().get(GlobalConstants.MAX_WAIT_TIME, TimeUnit.SECONDS);
    }

发送的时候会有最大等待时间，这个最大等待时间设置的10秒，如果未到10s，只有在连接主动关闭或者被动关闭的时候，该线程的阻塞才会结束，再联系到问题上，只有在两次发到第三方接口时才会出现这个问题，那是不是第一次调用第三方接口的时候，连接没有关呢？怒查代码。。 果然

仅仅启动了任务，对于第一次请求的资源没有清理，增加了一句话就搞定了。

ctx.close();

但是还有一个问题，为什么都是阻塞4到5秒呢？从上面的分析可以看到，一种是主动关闭连接还有一种是被动关闭连接，主动关闭设置的最大超时时间是10s，那么被动设置的多少呢，抓个包可以瞅瞅

可以看到大概花费了5秒左右，第三方将第一次请求的连接关闭掉了