一次介面超時排查，花費了我兩個星期。。

來源：https://zhenbianshu.github.io/

接著上次的排查，最近在查一個問題，花費了近兩個星期，我一定要總結一下，今天繼續，

Jdk 的 native 方法當然不是終點，雖然發現 Jdk、docker、作業系統 Bug 的可能性極小，但再往底層查卻很可能發現一些常見的配置錯誤，

為了便于復現，我用 JMH 寫了一個簡單的 demo，控制速度不斷地通過 log4j2 寫入日志，將專案打包成 jar 包，就可以很方便地在各處運行了，

@BenchmarkMode(Mode.AverageTime)
@OutputTimeUnit(TimeUnit.MICROSECONDS)
@State(Scope.Benchmark)
@Threads(5)
public class LoggerRunner {
    public static void main(String[] args) throws RunnerException {

        Options options = new OptionsBuilder()
                .include(LoggerRunner.class.getName())
                .warmupIterations(2)
                .forks(1)
                .measurementIterations(1000)
                .build();
        new Runner(options).run();
    }
}

我比較懷疑是 docker 的原因，但是在 docker 內外運行了 jar 包卻發現都能很簡單地復現日志停頓問題，而 jdk 版本眾多，我準備首先排查作業系統配置問題，

系統呼叫

strace 命令很早就使用過，不久前還用它分析過 shell 腳本執行慢的問題( 解決問題，別擴展問題)，但我還是不太習慣把 Java 和它聯系起來，幸好有部門的老司機指點，于是就使用 strace 分析了一波 Java 應用，

命令跟分析普通腳本一樣， strace -T -ttt -f -o strace.log java -jar log.jar， -T 選項可以將每一個系統呼叫的耗時列印到系統呼叫的結尾，當然排查時使用 -p pid 附加到 tomcat 上也是可以的，雖然會有很多容易混淆的系統呼叫，

對比 jmh 壓測用例輸出的 log4j2.info() 方法耗時，發現了下圖中的狀況，

一次 write 系統呼叫竟然消耗了 147ms，很明顯地，問題出在 write 系統呼叫上，

檔案系統

結構

這時候就要好好回想一下作業系統的知識了，

在 linux 系統中，萬物皆檔案，而為了給不同的介質提供一種抽象的介面，在應用層和系統層之間，抽象了一個虛擬檔案系統層（virtual file system, VFS），上層的應用程式通過 系統呼叫 system call 操作虛擬檔案系統，進而反饋到下層的硬體層，

由于硬碟等介質操作速度與記憶體不在同一個數量級上，為了平衡兩者之間的速度，linux 便把檔案映射到記憶體中，將硬碟單位塊(block)對應到記憶體中的一個 頁(page)上，這樣，當需要操作檔案時，直接操作記憶體就可以了，當緩沖區操作達到一定量或到達一定的時間后，再將變更統一刷到磁盤上，這樣便有效地減少了磁盤操作，應用也不必等待硬碟操作結束，回應速度得到了提升，

而 write 系統呼叫會將資料寫到記憶體中的 page cache，將 page 標記為 臟頁(dirty) 后回傳，

linux 的 writeback 機制

對于將記憶體緩沖區的內容刷到磁盤上，則有兩種方式：

首先，應用程式在呼叫 write 系統呼叫寫入資料時，如果發現 page cache 的使用量大于了設定的大小，便會主動將記憶體中的臟頁刷到硬碟上，在此期間，所有的 write 系統呼叫都會被阻塞，

系統當然不會容忍不定時的 write 阻塞，linux 還會定時啟動 pdflush 執行緒，判斷記憶體頁達到一定的比例或臟頁存活時間達到設定的時間，將這些臟頁刷回到磁盤上，以避免被動刷緩沖區，這種機制就是 linux 的 writeback 機制，

猜測

了解了以上基礎知識，那么對于 write 系統呼叫為什么會被阻塞，提出了兩種可能：

• page cache 可用空間不足，導致觸發了主動的 flush，此時會阻塞所有對此 device 的 write，
• 寫入程序被其他事務阻塞，

首先對于第一種可能：?查看系統配置 dirty_ratio 的大小：20，此值是 page cache 占用系統可用記憶體(real mem + swap)的最大百分比， 我們的記憶體為 32G，沒有啟用 swap，則實際可用的 page cache 大小約為 6G，

另外，與 pdflush 相關的系統配置：系統會每 vm.dirty_writeback_centisecs (5s) 喚醒一次 pdflush 執行緒， 發現臟頁比例超過 vm.dirty_background_ratio (10%) 或 臟頁存活時間超過 vm.dirty_expire_centisecs(30s) 時，會將臟頁刷回硬碟，

查看 /proc/meminfo 內 Dirty/Writeback 項的變化，并對比服務的檔案寫入速度，結論是資料會被 pdflush 刷回到硬碟，不會觸發被動 flush 以阻塞 write 系統呼叫，

ext4 的 journal 特性

write 被阻塞的原因

繼續搜索資料，在一篇文章(Why buffered writes are sometimes stalled )中看到 write 系統呼叫被阻塞有以下可能：

• 要寫入的資料依賴讀取的結果時，但記錄日志不依賴讀檔案；
• wirte page 時有別的執行緒在呼叫 fsync() 等主動 flush 臟頁的方法，但由于鎖的存在，log 在寫入時不會有其他的執行緒操作；
• 格式為 ext3/4 的檔案系統在記錄 journal log 時會阻塞 write，而我們的系統檔案格式為 ext4，維基百科上的一個條目（ https://en.wikipedia.org/wiki/Journaling_block_device ） 也描述了這種可能，

journal

journal 是 檔案系統保證資料一致性的一種手段，在寫入資料前，將即將進行的各個操作步驟記錄下來，一旦系統掉電，恢復時讀取這些日志繼續操作就可以了，但批量的 journal commit 是一個事務，flush 時會阻塞 write 的提交，

我們可以使用 dumpe2fs /dev/disk | grep features 查看磁盤支持的特性，其中有 has_journal 代表檔案系統支持 journal 特性，

ext4 格式的檔案系統在掛載時可以選擇 (jouranling、ordered、writeback) 三種之一的 journal 記錄模式，

三種模式分別有以下特性：

• journal：在將資料寫入檔案系統前，必須等待 metadata 和 journal 已經落盤了，
• ordered：不記錄資料的 journal，只記錄 metadata 的 journal 日志，且需要保證所有資料在其 metadata journal 被 commit 之前落盤，ext4 在不添加掛載引數時使用此模式，
• writeback: 資料可能在 metadata journal 被提交之后落盤，可能導致舊資料在系統掉電后恢復到磁盤中，

當然，我們也可以選擇直接禁用 journal，使用 tune2fs -O ^has_journal /dev/disk，只能操作未被掛載的磁盤，

猜測因為 journal 觸發了臟頁落盤，而臟頁落盤導致 write 被阻塞，所以解決 journal 問題就可以解決介面超時問題，

解決方案與壓測結果

以下是我總結的幾個介面超時問題的解決方案：

1. log4j2 日志模式改異步，但有可能會在系統重啟時丟失日志，另外在異步佇列 ringbuffer 被填滿未消費后，新日志會自動使用同步模式，
2. 調整系統刷臟頁的配置，將檢查臟頁和臟頁過期時間設定得更短(1s 以內)，但理論上會略微提升系統負載（未明顯觀察到），
3. 掛載硬碟時使用 data=https://www.cnblogs.com/javastack/p/writeback 選項修改 journal 模式，但可能導致系統重啟后檔案包含已洗掉的內容，
4. 禁用 ext4 的 journal 特性，但可能會導致系統檔案的不一致，
5. 把 ext4 的 journal 日志遷移到更快的磁盤上，如 ssd、閃存等，操作復雜，不易維護，
6. 使用 xfs、fat 等 檔案系統格式，特性不了解，影響不可知，

當然，對于這幾種方案，我也做了壓測，以下是壓測的結果，

小結

介面超時問題總算是告一段落，查了很久，不過解決它之后也非常有成就感，遺憾的是沒有在 linux 內核代碼中找到證據，160M 的代碼，分層也不熟悉，實在是無從查起，希望以后有機會能慢慢接觸吧，

程式員還是要懂些作業系統知識的，不僅幫我們在應對這種詭異的問題時不至于束手無策，也可以在做一些業務設計時能有所參考，

又熟悉了一些系統工具和命令，腳手架上又豐富了，

近期熱文推薦：

1.1,000+ 道 Java面試題及答案整理(2021最新版)

2.別在再滿屏的 if/ else 了，試試策略模式，真香！！

3.臥槽！Java 中的 xx ≠ null 是什么新語法？

4.Spring Boot 2.5 重磅發布，黑暗模式太炸了！

5.《Java開發手冊（嵩山版）》最新發布，速速下載！

覺得不錯，別忘了隨手點贊+轉發哦！

標籤：Java

上一篇：disruptor筆記之四：事件消費知識點小結

下一篇：案例分享 | dubbo 2.7.12 bug導致線上故障