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

寶路發表於2021-09-03

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

 

相關文章