近期業務大量突增微服務性能優化總結-3.針對 x86 雲環境改進異步日志等待策略

最近，業務增長的很迅猛，對於我們后台這塊也是一個不小的挑戰，這次遇到的核心業務接口的性能瓶頸，並不是單獨的一個問題導致的，而是幾個問題揉在一起：我們解決一個之后，發上線，之后發現還有另一個的性能瓶頸問題。這也是我經驗不足，導致沒能一下子定位解決；而我又對我們后台整個團隊有着固執的自尊，不想通過大量水平擴容這種方式挺過壓力高峰，導致線上連續幾晚都出現了不同程度的問題，肯定對於我們的業務增長是有影響的。這也是我不成熟和要反思的地方。這系列文章主要記錄下我們針對這次業務增長，對於我們后台微服務系統做的通用技術優化，針對業務流程和緩存的優化由於只適用於我們的業務，這里就不再贅述了。本系列會分為如下幾篇：

1. 改進客戶端負載均衡算法
2. 開發日志輸出異常堆棧的過濾插件
3. 針對 x86 雲環境改進異步日志等待策略
4. 增加對於同步微服務的 HTTP 請求等待隊列的監控以及雲上部署，需要小心達到實例網絡流量上限導致的請求響應緩慢
5. 針對系統關鍵業務增加必要的侵入式監控

針對 x86 雲環境改進異步日志等待策略

由於線上業務量級比較大（日請求上億，日活用戶幾十萬），同時業務涉及邏輯很復雜，線上日志級別我們采用的是 info 級別，導致線上日志量非常龐大，所以我們很早就使用了 Log4j2 異步日志。Log4j2 異步日志基於 Disruptor，其中的等待策略，本次優化前，我們選用的是 BLOCK。

Log4j2 異步日志的等待策略

Disruptor 的消費者做的事情其實就是不斷檢查是否有消息到來，其實就是某個狀態位是否就緒，就緒后讀取消息進行消費。至於如何不斷檢查，這個就是等待策略。Disruptor 中有很多等待策略，熟悉多處理器編程的對於等待策略肯定不會陌生，在這里可以簡單理解為當任務沒有到來時，線程應該如何等待並且讓出 CPU 資源才能在任務到來時盡量快的開始工作。在 Log4j2 中，異步日志基於 Disruptor，同時使用 AsyncLoggerConfig.WaitStrategy 這個環境變量對於 Disruptor 的等待策略進行配置，目前最新版本的 Log4j2 中可以配置：

switch (strategyUp) {
    case "SLEEP":
        final long sleepTimeNs =
                parseAdditionalLongProperty(propertyName, "SleepTimeNs", 100L);
        final String key = getFullPropertyKey(propertyName, "Retries");
        final int retries =
                PropertiesUtil.getProperties().getIntegerProperty(key, 200);
        return new SleepingWaitStrategy(retries, sleepTimeNs);
    case "YIELD":
        return new YieldingWaitStrategy();
    case "BLOCK":
        return new BlockingWaitStrategy();
    case "BUSYSPIN":
        return new BusySpinWaitStrategy();
    case "TIMEOUT":
        return new TimeoutBlockingWaitStrategy(timeoutMillis, TimeUnit.MILLISECONDS);
    default:
        return new TimeoutBlockingWaitStrategy(timeoutMillis, TimeUnit.MILLISECONDS);
}

本來，我們使用的是基於 Wait/Notify 的 BlockingWaitStrategy。但是這種策略導致業務量突增的時候，日志寫入線程在一段時間內一直未能被喚醒，導致 RingBuffer 中積壓了很多日志事件。

為何日志寫入線程未能被喚醒

首先簡單說一下一些硬件基礎。CPU 不是直接從內存中讀取數據，中間有好幾層 CPU 緩存。當前大多是多 CPU 架構，單機中使用 MESI 緩存一致性協議，當一個處理器訪問另一個處理器已經裝載入高速緩存的主存地址的時候，就會發生共享（sharing，或者稱為爭用 contention）。需要考慮緩存一致性的問題，因為如果一個處理器要更新共享的緩存行，則另一個處理器的副本需要作廢以免讀取到過期的值。

MESI 緩存一致性協議，緩存行存在以下四種狀態：

• Modified：緩存行被修改，最終一定會被寫回入主存，在此之前其他處理器不能再緩存這個緩存行。
• Exclusive：緩存行還未被修改，但是其他的處理器不能將這個緩存行載入緩存
• Shared：緩存行未被修改，其他處理器可以加載這個緩存行到緩存
• Invalid：緩存行中沒有有意義的數據

舉例：假設處理器和主存由總線連接，如圖所示：

a) 處理器 A 從地址 a 讀取數據，將數據存入他的高速緩存並置為 Exclusive

b) 處理器 B 從地址 a 讀取數據，處理器 A 檢測到地址沖突，響應緩存中 a 地址的數據，之后， 地址 a 的數據被 A 和 B 以 Shared 狀態裝入緩存

c) 處理器 B 對於 a 進行寫操作，狀態修改為 Modified，並廣播提醒 A（所有其他已經將該數據裝入緩存的處理器），狀態置為 Invalid。

d) 隨后 A 還需要訪問 a，它會廣播這個請求，B 將修改過的數據發到 A 和主存上，並且置兩個副本狀態為 Shared。

然后我們來看 Log4j2 異步日志的原理：Log4j2 異步日志基於高性能數據結構 Disruptor，Disruptor 是一個環形 buffer，做了很多性能優化（具體原理可以參考我的另一系列：高並發數據結構（disruptor）），Log4j2 對此的應用如下所示：

在消費端，只有一個單線程進行消費。當沒有日志到來時，線程需要等待，如何等待就是上面提到的等待策略。那么如何判斷就緒呢？其實這個線程就是不斷的檢查一個狀態位是否就緒，這里就是檢查 RingBuffer 的生產 offset 是否大於當前消費到的值，如果大於則代表有新消息需要消費。對於這種不斷檢查一個狀態位的代碼，被稱為 spin-wait loop。

那么為何業務高峰的時候，這個單線程喚醒的慢呢？主要原因是，業務量突增時，通常伴隨着大量遠大於 CPU 數量的線程進入 Runnable 狀態，同時伴隨着大量的 CPU 計算以及緩存行更新和失效，這會引起很大的總線流量，導致 Notify 信號被日志消費單線程感知受到影響的同時，日志消費單線程進入 Runnable 同時占有 CPU 資源進行運行也會受到影響。在這期間，可能活躍的業務線程占用較久的 CPU 時間，導致生產了很多日志事件進入 RingBuffer。

改用 SleepingWaitStrategy

我們這里改用其中策略最為均衡的 SleepingWaitStrategy。在當前的大多數應用中，線程的個數都遠大於 CPU 的個數，甚至是 RUNNABLE 的線程個數都遠大於 CPU 個數，使用基於 Wait 的 BusySpinWaitStrategy 會導致業務閑時突然來業務高峰的時候，日志消費線程喚醒的不夠及時（CPU 一直被大量的 RUNNABLE 業務線程搶占）。如果使用比較激進的 BusySpinWaitStrategy（一直調用 Thread.onSpinWait()）或者 YieldingWaitStrategy（先 SPIN 之后一直調用 Thread.yield()），則閑時也會有較高的 CPU 占用。我們期望的是一種遞進的等待策略，例如：

1. 在一定次數內，不斷 SPIN，應對日志量特別多的時候，減少線程切換消耗。
2. 在超過一定次數之后，開始不斷的調用 Thread.onSpinWait() 或者 Thread.yield()，使當前線程讓出 CPU 資源，應對間斷性的日志高峰。
3. 在第二步達到一定次數后，使用 Wait，或者 Thread.sleep() 這樣的函數阻塞當前線程，應對日志低峰的時候，減少 CPU 消耗。

SleepingWaitStrategy 就是這樣一個策略，第二步采用的是 Thread.yield()，第三步采用的是 Thread.sleep()。

public final class SleepingWaitStrategy implements WaitStrategy
{

    @Override
    public long waitFor(
        final long sequence, Sequence cursor, final Sequence dependentSequence, final SequenceBarrier barrier)
        throws AlertException
    {
        long availableSequence;
        int counter = retries;

        while ((availableSequence = dependentSequence.get()) < sequence)
        {
            counter = applyWaitMethod(barrier, counter);
        }

        return availableSequence;
    }

    @Override
    public void signalAllWhenBlocking()
    {
    }

    private int applyWaitMethod(final SequenceBarrier barrier, int counter)
        throws AlertException
    {
        barrier.checkAlert();
        //大於 100 的時候，spin
        //默認 counter 從 200 開始
        if (counter > 100)
        {
            --counter;
        }
        //在 0~ 100 之間
        else if (counter > 0)
        {
            --counter;
            Thread.yield();
        }
        //最后，使用 sleep
        else
        {
            LockSupport.parkNanos(sleepTimeNs);
        }

        return counter;
    }
}

將其中的 Thread.yield 改為 Thread.onSpinWait

我們發現，使用 SleepingWaitStrategy 之后，通過我們自定義的 JFR 事件發現，在業務低峰到業務突增的時候，線程總是在 Thread.yield() 的時候有日志事件到來。但是每次線程執行 Thread.yield() 的時間間隔還是有點長，並且有日志事件到來了但是還是能觀察到再過幾個 Thread.yield() 之后，線程才發現有日志過來的情況。

所以，我們修改其中的 Thread.yield() 為 Thread.onSpinWait()，原因是：我們部署到的環境是 x86 的機器，在 x86 的環境下 Thread.onSpinWait() 在被調用一定次數后，C1 編譯器就會將其替換成使用 PAUSE 這個 x86 指令實現。參考 JVM 源碼：

x86.ad

instruct onspinwait() %{
  match(OnSpinWait);
  ins_cost(200);

  format %{
    $$template
    $$emit$$"pause\t! membar_onspinwait"
  %}
  ins_encode %{
    __ pause();
  %}
  ins_pipe(pipe_slow);
%}

我們知道，CPU 並不會總直接操作內存，而是以緩存行讀取后，緩存在 CPU 高速緩存上。但是對於這種不斷檢查檢查某個狀態位是否就緒的代碼，不斷讀取 CPU 高速緩存，會在當前 CPU 從總線收到這個 CPU 高速緩存已經失效之前，都認為這個狀態為沒有變化。在業務忙時，總線可能非常繁忙，導致 SleepingWaitStrategy 的第二步一直檢查不到狀態位的更新導致進入第三步。

PAUSE 指令（參考：https://www.felixcloutier.com/x86/pause）是針對這種等待策略實現而產生的一個特殊指令，它會告訴處理器所執行的代碼序列是一個不斷檢查某個狀態位是否就緒的代碼（即 spin-wait loop），這樣的話，然后 CPU 分支預測就會據這個提示而避開內存序列沖突，CPU 就不會將這塊讀取的內存進行緩存，也就是說對 spin-wait loop 不做緩存，不做指令
重新排序等動作。從而提高 spin-wait loop 的執行效率。

這個指令使得針對 spin-wait loop 這種場景，Thread.onSpinWait()的效率要比 Thread.yield() 的效率要高。所以，我們修改 SleepingWaitStrategy 的 Thread.yield() 為 Thread.onSpinWait()。

微信搜索“我的編程喵”關注公眾號，每日一刷，輕松提升技術，斬獲各種offer：