记一次测试环境压测问题深究

1. 说明

　　Connection reset by peer异常算是老生常谈的问题了，在度娘上一搜一大堆结果，今天借助我们测试环境的一个遇到的现象，给大家一个不一样的视角，顺带总结下我的解决方案。

2. 背景简述

　　近日在测试环境，组员在做某个项目稳定性场景测试，执行1小时后TPS断崖式下跌，然后随着时间的推移，TPS曲线呈现逐渐下跌的趋势。。。。

组员经过与开发沟通初步定为是日志持久化导致，关闭日志持久化功能，复测现象消失。开发优化日志持久化机制，复测后TPS曲线表现平稳。

当然了，优化的不仅仅是这些，我们也对GC参数做了优化调整。然而组员执行稳定性测试过程中，我却发现被测服务器日志在疯狂的刷Connection reset by peer异常:

2021-08-28 11:01:32.224 - -  WARN  73613153 pool-5-thread-159 - - -  o.a.m.core.service.IoHandlerAdapter [-, -, -] exceptionCaught 55 - EXCEPTION, please implement com.xxxx.xxx.communication.mina.minashortconn.ServerHandler.exceptionCaught() for proper handling:
java.io.IOException: Connection reset by peer
  at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
  at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
  at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
  at sun.nio.ch.IOUtil.read(IOUtil.java:197)
  at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:379)
  at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:273)
  at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:44)
  at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:690)
  at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:664)
  at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:653)
  at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPollingIoProcessor.java:67)
  at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1124)
  at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
  at java.lang.Thread.run(Thread.java:748)

　　但从JMeter测试工具看到的确实每个Sampler的断言结果均是成功的。

3. 问题深究

　根据经验来看，这个现象很不正常，只用了很小小并发压测还不至于把链接队列压满。

　　首先，宝路先从组员编写的测试脚本分析，确实发现了问题，混合测试场景中，固定有三个socket接口会导致被测服务器抛出connection reset by peer异常。

然后，采用JMeter单笔发送这三个接口，也会出现此现象，这就更加验证了宝路的经验推测，不是连接队列溢出导致此现象。通过查看脚本发现了一些端倪：

每个接口均需要设置EOL，未设置就会出现Error reading from server,bytes read xxx 异常，如图：

下面我们从JMeter源码层面看下为啥会报此异常：

TCPClientImpl 部分源码：

@Override
    public String read(InputStream is, SampleResult sampleResult) throws ReadException{
        ByteArrayOutputStream w = new ByteArrayOutputStream();
        try {
            byte[] buffer = new byte[4096];
            int x;
            boolean first = true;
            while ((x = is.read(buffer)) > -1) {
                if (first) {
                    sampleResult.latencyEnd();
                    first = false;
                }
                w.write(buffer, 0, x);
                if (useEolByte && (buffer[x - 1] == eolByte)) {
                    break;
                }
            }

            // do we need to close byte array (or flush it?)
            if(log.isDebugEnabled()) {
                log.debug("Read: {}
{}", w.size(), w.toString());
            }
            return w.toString(CHARSET);
        } catch (IOException e) {
            throw new ReadException("Error reading from server, bytes read: " + w.size(), e, w.toString());
        }
    }

结合源码，如果服务器端返回的内容并不是有一个明确的终止符（在“TCP取样器”中设定的“End of line(EOL) byte value”）字节流，那么第8行代码：

x = is.read(buffer)) > -1

read会被阻塞，直至抛出读超时异常，此异常会被TCPSampler类中的sample方法51-54行捕获并继续处理：

TCPSampler部分源码：

@Override
    public SampleResult sample(Entry e)// Entry tends to be ignored ...
   {
        if (firstSample) { // Do stuff we cannot do as part of threadStarted()
            initSampling();
            firstSample=false;
        }
        final boolean reUseConnection = isReUseConnection();
        final boolean closeConnection = isCloseConnection();
        String socketKey = getSocketKey();
        if (log.isDebugEnabled()){
            log.debug(getLabel() + " " + getFilename() + " " + getUsername() + " " + getPassword());
        }
        SampleResult res = new SampleResult();
        boolean isSuccessful = false;
        res.setSampleLabel(getName());// Use the test element name for the label
        String sb = "Host: " + getServer() +
                " Port: " + getPort() + "
" +
                "Reuse: " + reUseConnection +
                " Close: " + closeConnection + "
[" +
                "SOLINGER: " + getSoLinger() +
                " EOL: " + getEolByte() +
                " noDelay: " + getNoDelay() +
                "]";
        res.setSamplerData(sb);
        res.sampleStart();
        try {
            Socket sock;
            try {
                sock = getSocket(socketKey);
            } finally {
                res.connectEnd();
            }
            if (sock == null) {
                res.setResponseCode("500"); //$NON-NLS-1$
                res.setResponseMessage(getError());
            } else if (protocolHandler == null){
                res.setResponseCode("500"); //$NON-NLS-1$
                res.setResponseMessage("Protocol handler not found");
            } else {
                currentSocket = sock;
                InputStream is = sock.getInputStream();
                OutputStream os = sock.getOutputStream();
                String req = getRequestData();
                // TODO handle filenames
                res.setSamplerData(req);
                protocolHandler.write(os, req);
                String in = protocolHandler.read(is, res);
                isSuccessful = setupSampleResult(res, in, null, protocolHandler);
            }
        } catch (ReadException ex) {
            log.error("", ex);
            isSuccessful=setupSampleResult(res, ex.getPartialResponse(), ex,protocolHandler);
            closeSocket(socketKey);
        } catch (Exception ex) {
            log.error("", ex);
            isSuccessful=setupSampleResult(res, "", ex, protocolHandler);
            closeSocket(socketKey);
        } finally {
            currentSocket = null;
            // Calculate response time
            res.sampleEnd();

            // Set if we were successful or not
            res.setSuccessful(isSuccessful);

            if (!reUseConnection || closeConnection) {
                closeSocket(socketKey);
            }
        }
        return res;
    }


其中setupSampleResult 方法会传入的异常进行判断，部分代码逻辑：

if(exception==null) {
    sampleResult.setResponseCodeOK();
    sampleResult.setResponseMessage("OK"); //$NON-NLS-1$
} else {
    sampleResult.setResponseCode("500"); //$NON-NLS-1$
    sampleResult.setResponseMessage(exception.toString()); //$NON-NLS-1$
}
 boolean isSuccessful = exception == null;

至此，大家应该就明白了，为什么JMeter的查看结果树显示交易失败。

下面我们从网络层面看下，到底发生什么，此时网络分析利器wireshrk就派上了用场，话不多说上包：

说明：脚本中tcp采样器的eol设置为32，29.73、27.94均为Linux虚机

在最后客户端向服务端发起重置连接，后续并没有四次挥手过程。在服务器端日志可看到：java.io.IOException: Connection reset by peer 异常。

从网络包分析看，服务器已经向客户端发了总长度为5202的响应报文，客户端也收到了全部长度，但为什么客户端却又向服务端发了RST呢，此时还是有些疑惑。

由于Linux执行JMeter并没有windows的GUI模式直观，于是宝路在windows机器上对现象进行了复现：

嗯？有点意思！客户端在确认收到服务器端发送4608长度报文后就发起了FIN，客户端主动申请关闭连接，又向服务器发送RST,ACK；可是此时服务端数据还没发送完毕，又向客户端发了594长度，结果客户端向服务器端回了RST。

从JMeter的查看结果数看到了只收到了4096长度，这也差的太远了吧！

不对吧，不应该是5202长度么。。。为啥只收到了4096长度啊？原因详见TCPClientImpl 源码第5，刚好返回报文的4096长度处是空格(eol值为32)。

宝路又发现个奇怪的现象，采用windows机器往Linux27.94服务器发交易，

在服务器端并没有出现java.io.IOException: Connection reset by peer 异常。

看来是被包欺骗了。。。。。？仔细比较两个包后，还发现了明显不一样的地方：

- win客户端在收到4608长度后，向客户主动FIN申请关闭连接，而Linux客户端却没有发送FIN
- win客户在主动FIN后，紧跟着就向客户端发送了RST,ACK报文，最后还发了RST，而Linux客户仅发了RST,ACK报文就结束了

在度娘上查了相关资料确实有了新的发现：

Linux内核net/ipv4/tcp.c中的tcp_close() 函数：

  /* As outlined in RFC 2525, section 2.17, we send a RST here because
   * data was lost. To witness the awful effects of the old behavior of
   * always doing a FIN, run an older 2.1.x kernel or 2.0.x, start a bulk
   * GET in an FTP client, suspend the process, wait for the client to
   * advertise a zero window, then kill -9 the FTP client, wheee...
   * Note: timeout is always zero in such a case.
   */
  if (data_was_unread) {
      /* Unread data was tossed, zap the connection. */
      NET_INC_STATS_USER(sock_net(sk), LINUX_MIB_TCPABORTONCLOSE);
      tcp_set_state(sk, TCP_CLOSE);
      tcp_send_active_reset(sk, sk->sk_allocation);
  }

如果你的接收缓冲区还有数据，协议栈就会发送RST来代替FIN。

那为什么win客户并未导致服务端出现Connection reset by peer 异常呢，从目前看分析看是跟FIN包和最后的RST包有关，根本原因宝路觉得还是不同操作系统的处理机制与大部分系统不一样导致的

4. 解決方案

现在，可以肯定返回报文没接收全，客户端主动申请关闭链接，导致的此问题的出现，那么怎么解决呢？

在度娘上还是找到了解决方案，基于JMeter的TCP采样器源码进行改造：

文章作者是根据JMeter4.1版本进行了改造，单独构建了一个新的tcp包，将JMeter的ApacheJMeter_tcp.jar替换即可。
宝路很久之前就跟大家提到过，最好还是构建成插件包，每次升级新高版本JMeter仅需把插件迁移过去即可，总不能把改过的代码再迁移到高版本的JMeter中吧，这样会浪费大把的时间。

基于这个思路，宝路参考文章代码基于JMeter官方5.4.1版本（当前最新版本），做成了插件包。

调整脚本设置：不设置EOL，将相应报文长度设置成5202长度

执行后发现，并未得到我们想要的结果，从JMeter的查看结果数看到了只收到了4608长度，后面的594长度并没有接收到。

嗯？那Linux机客户端的收到多少？于是乎。。。

策略调整脚本：增加后置处理器打印返回报文长度，结果发现Linux客户端收到的报文却与win客户端一致长度均是4608

由此可见新的读取代码逻辑扔不能保证完全读取指定长度：

intx = 0;
buffer = new byte[length];
if ((x = is.read(buffer, 0, length)) > -1) {
   sampleResult.latencyEnd();
   w.write(buffer, 0, x);
}

这里的 length 即从插件页面设置的要读取的响应报文长度。

也就是说JDK的InputStream的read(buffer, 0, length) 不保证能完全读取预期长度。

那么怎么解决呢？最新优化代码如下：

intx = 0;
int y = 0;//已读取字节长度
buffer = new byte[length];
bis = new BufferedInputStream(is);
while ((x = bis.read(buffer, 0, length)) > -1) {
    if (first) {
        sampleResult.latencyEnd();
        first = false;
    }
    y+=x;
    w.write(buffer, 0, x);
    if (y >= length) {
        break;
    }
}

　　我们再来执行下：

win机器

Linux机器

嘿嘿！都接收到了预期报文长度！在使用Linux发送交易时，服务器端并未抛出 Connection reset by peer 异常。

宝路跟组员第一时间在测试环境对插件进行并发验证，问题得到完美解决！就在今日凌晨，我们也利用此插件完成线上超高吞吐量压测任务！

5. 结语

终于把这篇文章写完了，不忘初心，争取给大家带来更多有价值的分享！脑袋还有点沉，我再去睡会！对了，目前该插件已在 baolu-jmeter-plugins 文章中更新，欢迎下载体验！

巨人肩膀：

https://github.com/XMeterSaaSService/Blog_sample_project/tree/master/tcp/src/protocol/tcp/org/apache/jmeter/protocol/tcp