近期業務大量突增微服務效能最佳化總結-3.改進非同步日誌等待策略

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

改進客戶端負載均衡演算法

開發日誌輸出異常堆疊的過濾外掛

針對 x86 雲環境改進非同步日誌等待策略

增加對於同步微服務的 HTTP 請求等待佇列的監控以及雲上部署,需要小心達到例項網路流量上限導致的請求響應緩慢

針對系統關鍵業務增加必要的侵入式監控

針對 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

:快取行中沒有有意義的資料

舉例:假設處理器和主存由匯流排連線,如圖所示:

近期業務大量突增微服務效能最佳化總結-3.改進非同步日誌等待策略

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 對此的應用如下所示:

近期業務大量突增微服務效能最佳化總結-3.改進非同步日誌等待策略

在消費端,只有一個單執行緒進行消費。當沒有日誌到來時,執行緒需要等待,如何等待就是上面提到的等待策略。那麼如何判斷就緒呢?其實這個執行緒就是不斷的檢查一個狀態位是否就緒,這裡就是檢查 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 佔用。我們期望的是一種遞進的等待策略,例如:

在一定次數內,不斷 SPIN,應對日誌量特別多的時候,減少執行緒切換消耗。

在超過一定次數之後,開始不斷的呼叫 Thread。onSpinWait() 或者 Thread。yield(),使當前執行緒讓出 CPU 資源,應對間斷性的日誌高峰。

在第二步達到一定次數後,使用 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()。