從時延毛刺問題定位到 Netty 的效能統計設計

一、背景：

通常情況下，使用者以黑盒的方式使用Netty，透過Netty完成協議訊息的讀取和傳送，以及編解碼操作，不需要關注Netty的底層實現細節。

在高併發場景下，往往需要統計系統的關鍵效能KPI資料，結合日誌、告警等對故障進行定位分析，如果對Netty的底層實現細節不瞭解，獲取哪些關鍵效能資料，以及資料正確的獲取方式都將成為難點。錯誤或者不準確的資料可能誤導定位思路和方向，導致問題遲遲不能得到正確解決。

二、時延毛刺故障排查的艱辛歷程:

問題現象：某電商生產環境在業務高峰期，偶現服務呼叫時延突刺問題，時延突然增大的服務沒有固定規律，問題發生的比例雖然很低，但是對客戶的體驗影響很大，需要儘快定位出問題原因並解決。

• 時延毛刺問題初步分析：

服務呼叫時延增大，但並不是異常，因此執行日誌並不會列印ERROR日誌，單靠傳統的日誌無法進行有效問題定位。利用分散式訊息跟蹤系統，進行分散式環境的故障定界。

透過對服務呼叫時延進行排序和過濾，找出時延增大的服務呼叫鏈詳細資訊，發現業務服務端處理很快，但是消費者統計資料卻顯示服務端處理非常慢，呼叫鏈兩端看到的資料不一致，怎麼回事？

對呼叫鏈的詳情進行分析發現，服務端列印的時延是業務服務介面呼叫的耗時，並沒有包含：

（1）服務端讀取請求訊息、對訊息做解碼，以及內部訊息投遞、線上程池訊息佇列排隊等待的時間。

（2）響應訊息編碼時間、訊息佇列傳送排隊時間以及訊息寫入到Socket傳送緩衝區的時間。

服務呼叫鏈的工作原理如下：

圖1 服務呼叫鏈工作原理

將呼叫鏈中的訊息呼叫過程詳細展開，以服務端讀取請求和傳送響應訊息為例進行說明，如下圖所示：

圖2 服務端呼叫鏈詳情

對於服務端的處理耗時，除了業務服務自身呼叫的耗時之外，還應該包含服務框架的處理時間，具體如下：

（1）請求訊息的解碼（反序列化）時間。

（2）請求訊息在業務執行緒池中排隊等待執行時間。

（3）響應訊息編碼（序列化）時間。

（4）響應訊息ByteBuf在傳送佇列的排隊時間。

由於服務端呼叫鏈只採集了業務服務介面的呼叫耗時，沒有包含服務框架本身的排程和處理時間，導致無法對故障進行定界：服務端沒有統計服務框架的處理時間，因此不排除問題出在訊息傳送佇列或者業務執行緒池佇列積壓而導致時延變大。

• 服務呼叫鏈改進：

對服務呼叫鏈埋點進行最佳化，具體措施如下：

（1）包含客戶端和服務端訊息編碼和解碼的耗時。

（2）包含請求和應答訊息在佇列中的排隊時間。

（3）包含應答訊息在通訊執行緒傳送佇列（陣列）中的排隊時間。

同時，為了方便問題定位，增加列印輸出Netty的效能統計日誌，主要包括：

（1）當前系統的總鏈路數、以及每個鏈路的狀態。

（2）每條鏈路接收的總位元組數、週期T接收的位元組數、訊息接收吞吐量。

（3）每條鏈路傳送的總位元組數、週期T傳送的位元組數、訊息傳送吞吐量。

對服務呼叫鏈最佳化之後，上線執行一段時間，透過分析比對Netty效能統計日誌、呼叫鏈日誌，發現雙方的資料並不一致，Netty效能統計日誌統計到的資料與前端門戶看到的也不一致，因此懷疑是新增的效能統計功能存在BUG，需要繼續對問題進行定位。

• 都是同步思維惹的禍:

傳統的同步服務呼叫，發起服務呼叫之後，業務執行緒阻塞，等待響應，接收到響應之後，業務執行緒繼續執行，對傳送的訊息進行累加，獲取效能KPI資料。

使用Netty之後，所有的網路I/O操作都是非同步執行的，即呼叫Channel的write方法，並不代表訊息真正傳送到TCP緩衝區中，如果在呼叫write方法之後就對傳送的位元組數做計數，統計結果就不準確。

對訊息傳送功能進行code review，發現程式碼呼叫完writeAndFlush方法之後直接對傳送的請求訊息位元組數進行計數，程式碼示例如下：

 public void channelRead(ChannelHandlerContextctx, Object msg) {

        int sendBytes =((ByteBuf)msg).readableBytes();

        ctx.writeAndFlush(msg);

        totalSendBytes.getAndAdd(sendBytes);

}

呼叫writeAndFlush並不代表訊息已經傳送到網路上，它僅僅是個非同步的訊息傳送操作而已，呼叫writeAndFlush之後，Netty會執行一系列操作，最終將訊息傳送到網路上，相關流程如下所示：

圖3 writeAndFlush處理流程圖

透過對writeAndFlush方法深入分析，我們發現效能統計程式碼忽略瞭如下幾個耗時：

（1）業務ChannelHandler的執行時間。

（2）被非同步封裝的WriteTask/WriteAndFlushTask在NioEventLoop任務佇列中的排隊時間。

（3）ByteBuf在ChannelOutboundBuffer佇列中排隊時間。

（4）JDK NIO類庫將ByteBuffer寫入到網路的時間。

由於效能統計遺漏了上述4個關鍵步驟的執行時間，因此統計出來的傳送速率比實際值會更高一些，這將干擾我們的問題定位思路。

• 正確的訊息傳送速率效能統計策略:

正確的訊息傳送速率效能統計方法如下：

（1）呼叫writeAndFlush方法之後獲取ChannelFuture。

（2）新增訊息傳送ChannelFutureListener並註冊到ChannelFuture中，監聽訊息傳送結果，如果訊息寫入SocketChannel成功，則Netty會回撥ChannelFutureListener的operationComplete方法。

（3）在訊息傳送ChannelFutureListener的operationComplete方法中進行效能統計。

正確的效能統計程式碼示例如下：

public voidchannelRead(ChannelHandlerContext ctx, Object msg) {

        int sendBytes =((ByteBuf)msg).readableBytes();

        ChannelFuture writeFuture =ctx.write(msg);

        writeFuture.addListener((f) ->

        {

           totalSendBytes.getAndAdd(sendBytes);

        });

        ctx.flush();

}

對Netty訊息傳送相關原始碼進行分析，當傳送的位元組數大於0時，進行ByteBuf的清理工作，程式碼如下：

protected voiddoWrite(ChannelOutboundBuffer in) throws Exception {

    //程式碼省略...

     if (localWrittenBytes <= 0) {

                        incompleteWrite(true);

                        return;

                    }

                   adjustMaxBytesPerGatheringWrite(attemptedBytes, localWrittenBytes,maxBytesPerGatheringWrite);

                    in.removeBytes(localWrittenBytes);

                    --writeSpinCount;

                    break;

//程式碼省略...

}

接著分析ChannelOutboundBuffer的removeBytes(long writtenBytes)方法，將傳送的位元組數與當前ByteBuf可讀的位元組數進行對比，判斷當前的ByteBuf是否完成傳送，如果完成則呼叫remove()清理它，否則只更新下傳送進度，相關程式碼如下：

protected voiddoWrite(ChannelOutboundBuffer in) throws Exception {

    //程式碼省略...

      if (readableBytes <=writtenBytes) {

                if (writtenBytes != 0) {

                    progress(readableBytes);

                    writtenBytes -=readableBytes;

                }

                remove();

            } else {

                if (writtenBytes != 0) {

                    buf.readerIndex(readerIndex+ (int) writtenBytes);

                    progress(writtenBytes);

                }

                break;

            }

//程式碼省略...

}

當呼叫remove()方法時，最終會呼叫訊息傳送ChannelPromise的trySuccess方法，通知監聽Listener訊息已經完成傳送，相關程式碼如下所示：

public booleantrySuccess(V result) {

//程式碼省略...

        if (setSuccess0(result)) {

            notifyListeners();

            return true;

        }

        return false;

    }

//程式碼省略...

}

經過以上分析可以看出，呼叫write/writeAndFlush方法本身並不代表訊息已經傳送完成，只有監聽write/writeAndFlush的操作結果，在非同步回撥監聽中計數，結果才更精確。

需要注意的是，非同步回撥通知由Netty的NioEventLoop執行緒執行，即便非同步回撥程式碼寫在業務執行緒中，也是由Netty的I/O執行緒來執行累加計數的，因此這塊兒需要考慮多執行緒併發安全問題，呼叫堆疊示例如下：

圖4 訊息傳送結果非同步回撥通知執行執行緒

如果訊息報文比較大，或者一次批次傳送的訊息比較多，可能會出現“寫半包”問題，即一個訊息無法在一次write操作中全部完成傳送，可能只傳送了一半，針對此類場景，可以建立GenericProgressiveFutureListener用於實時監聽訊息傳送進度，做更精準的統計，相關程式碼如下所示：

privatestatic void notifyProgressiveListeners0(

            ProgressiveFuture<?> future,GenericProgressiveFutureListener<?>[] listeners, long progress,long total) {

        for(GenericProgressiveFutureListener<?> l: listeners) {

            if (l == null) {

                break;

            }

            notifyProgressiveListener0(future,l, progress, total);

        }

}

問題定位出來之後，按照正確的做法對Netty效能統計程式碼進行了修正，上線之後，結合呼叫鏈日誌，很快定位出了業務高峰期偶現的部分服務時延毛刺較大問題，最佳化業務執行緒池引數配置之後問題得到解決。

• 常見的訊息傳送效能統計誤區:

在實際業務中比較常見的效能統計誤區如下：

（1）呼叫write/ writeAndFlush方法之後就開始統計傳送速率。

（2）訊息編碼時進行效能統計：編碼之後，獲取out可讀的位元組數，然後做累加。編碼完成並不代表訊息被寫入到SocketChannel中，因此效能統計也不準確。

• Netty關鍵效能指標採集:

除了訊息傳送速率，還有其它一些重要的指標需要採集和監控，無論是在呼叫鏈詳情中展示，還是統一由運維採集、彙總和展示，這些效能指標對於故障的定界和定位幫助都很大。

• Netty I/O執行緒池效能指標:

Netty I/O執行緒池除了負責網路I/O訊息的讀寫，還需要同時處理普通任務和定時任務，因此訊息佇列積壓的任務個數是衡量Netty I/O執行緒池工作負載的重要指標。由於Netty NIO執行緒池採用的是一個執行緒池/組包含多個單執行緒執行緒池的機制，因此不需要像原生的JDK執行緒池那樣統計工作執行緒數、最大執行緒數等。相關程式碼如下所示：

publicvoid channelActive(ChannelHandlerContext ctx) throws Exception {

kpiExecutorService.scheduleAtFixedRate(()->

        {

            Iterator<EventExecutor>executorGroups = ctx.executor().parent().iterator();

            while (executorGroups.hasNext())

            {

                SingleThreadEventExecutorexecutor = (SingleThreadEventExecutor)executorGroups.next();

                int size = executor.pendingTasks();

                if (executor == ctx.executor())

                   System.out.println(ctx.channel() + "--> " + executor +" pending size in queue is : --> " + size);

                else

                    System.out.println(executor+ " pending size in queue is : --> " + size);

            }

        },0,1000, TimeUnit.MILLISECONDS);

   }

}

執行結果如下所示：

圖5 Netty I/O執行緒池效能統計KPI資料

• Netty傳送佇列積壓訊息數：

Netty訊息傳送佇列積壓數可以反映網路速度、通訊對端的讀取速度、以及自身的傳送速度等，因此對於服務呼叫時延的精細化分析對於問題定位非常有幫助，它的採集方式程式碼示例如下：

publicvoid channelActive(ChannelHandlerContext ctx) throws Exception {

writeQueKpiExecutorService.scheduleAtFixedRate(()->

        {

            long pendingSize =((NioSocketChannel)ctx.channel()).unsafe().outboundBuffer().totalPendingWriteBytes();

            System.out.println(ctx.channel() +"--> " + " ChannelOutboundBuffer's totalPendingWriteBytes is: "

                    + pendingSize + "bytes");

        },0,1000, TimeUnit.MILLISECONDS);

}

執行結果如下：

圖6 Netty Channel對應的訊息傳送佇列效能KPI資料

由於totalPendingSize是volatile的，因此統計執行緒即便不是Netty的I/O執行緒，也能夠正確的讀取其最新值。

• Netty訊息讀取速率效能統計:

針對某個Channel的訊息讀取速率效能統計，可以在解碼ChannelHandler之前新增一個效能統計ChannelHandler，用來對讀取速率進行計數，相關程式碼示例如下(ServiceTraceProfileServerHandler類)：

public voidchannelActive(ChannelHandlerContext ctx) throws Exception {

       kpiExecutorService.scheduleAtFixedRate(()->

        {

            int readRates =totalReadBytes.getAndSet(0);

            System.out.println(ctx.channel() +"--> read rates " + readRates);

        },0,1000, TimeUnit.MILLISECONDS);

        ctx.fireChannelActive();

    }

    public void channelRead(ChannelHandlerContextctx, Object msg) {

        int readableBytes =((ByteBuf)msg).readableBytes();

        totalReadBytes.getAndAdd(readableBytes);

        ctx.fireChannelRead(msg);

}

執行結果如下所示：

圖7  NettyChannel 訊息讀取速率效能統計

三、總結：

本文選自《Netty進階之路：跟著案例學Netty》一書，由電子工業出版社出版，李林鋒著。

當我們需要對服務呼叫時延進行精細化分析時，需要把Netty通訊框架底層的處理耗時資料也採集走並進行分析，由於Netty的I/O操作都是非同步的，因此不能像傳統同步呼叫那樣的思路去做效能資料統計，需要註冊效能統計監聽器，在非同步回撥中完成計數。另外，Netty的I/O執行緒池、訊息傳送佇列等實現比較特殊，與傳統的Tomcat等框架實現策略不同，因此對於Netty的關鍵效能KPI資料採集不能照搬JDK和Tomcat的做法。

作者簡介：10年Java NIO通訊框架、平臺中介軟體（SOA、PaaS、微服務框架等）架構設計和開發經驗，目前在華為終端應用市場負責業務微服務化、雲化、全球化等相關架構設計和開發工作，《Netty權威指南》、《分散式服務框架原理與實踐》作者，愛好技術分享和寫作。