記一次測試環境壓測問題深究

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: {}\n{}", 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() + "\n" +
                "Reuse: " + reUseConnection +
                " Close: " + closeConnection + "\n[" +
                "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