从应用到内核查接口超时（中）
應(yīng)用復(fù)現(xiàn)
接著上文?從應(yīng)用到內(nèi)核查接口超時(shí)（上）?繼續(xù)排查導(dǎo)致接口超時(shí)的原因。
轉(zhuǎn)載隨意，文章會(huì)持續(xù)修訂，請注明來源地址：https://zhenbianshu.github.io?。
Jdk 的 native 方法當(dāng)然不是終點(diǎn)，雖然發(fā)現(xiàn) Jdk、docker、操作系統(tǒng) Bug 的可能性極小，但再往底層查卻很可能發(fā)現(xiàn)一些常見的配置錯(cuò)誤。
為了便于復(fù)現(xiàn)，我用 JMH 寫了一個(gè)簡單的 demo，控制速度不斷地通過 log4j2 寫入日志。將項(xiàng)目打包成 jar 包，就可以很方便地在各處運(yùn)行了。
@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 內(nèi)外運(yùn)行了 jar 包卻發(fā)現(xiàn)都能很簡單地復(fù)現(xiàn)日志停頓問題。而 jdk 版本眾多，我準(zhǔn)備首先排查操作系統(tǒng)配置問題。
系統(tǒng)調(diào)用
strace 命令很早就使用過，不久前還用它分析過 shell 腳本執(zhí)行慢的問題(?解決問題，別擴(kuò)展問題)，但我還是不太習(xí)慣把 Java 和它聯(lián)系起來，幸好有部門的老司機(jī)指點(diǎn)，于是就使用 strace 分析了一波 Java 應(yīng)用。
命令跟分析普通腳本一樣，?strace -T -ttt -f -o strace.log java -jar log.jar， -T 選項(xiàng)可以將每一個(gè)系統(tǒng)調(diào)用的耗時(shí)打印到系統(tǒng)調(diào)用的結(jié)尾。當(dāng)然排查時(shí)使用 -p pid 附加到 tomcat 上也是可以的，雖然會(huì)有很多容易混淆的系統(tǒng)調(diào)用。
對比 jmh 壓測用例輸出的 log4j2.info() 方法耗時(shí)，發(fā)現(xiàn)了下圖中的狀況。
一次 write 系統(tǒng)調(diào)用竟然消耗了 147ms，很明顯地，問題出在 write 系統(tǒng)調(diào)用上。
文件系統(tǒng)
結(jié)構(gòu)
這時(shí)候就要好好回想一下操作系統(tǒng)的知識了。
在 linux 系統(tǒng)中，萬物皆文件，而為了給不同的介質(zhì)提供一種抽象的接口，在應(yīng)用層和系統(tǒng)層之間，抽象了一個(gè)虛擬文件系統(tǒng)層（virtual file system, VFS）。上層的應(yīng)用程序通過 系統(tǒng)調(diào)用 system call 操作虛擬文件系統(tǒng)，進(jìn)而反饋到下層的硬件層。
由于硬盤等介質(zhì)操作速度與內(nèi)存不在同一個(gè)數(shù)量級上，為了平衡兩者之間的速度，linux 便把文件映射到內(nèi)存中，將硬盤單位塊(block)對應(yīng)到內(nèi)存中的一個(gè) 頁(page)上。這樣，當(dāng)需要操作文件時(shí)，直接操作內(nèi)存就可以了。當(dāng)緩沖區(qū)操作達(dá)到一定量或到達(dá)一定的時(shí)間后，再將變更統(tǒng)一刷到磁盤上。這樣便有效地減少了磁盤操作，應(yīng)用也不必等待硬盤操作結(jié)束，響應(yīng)速度得到了提升。
而 write 系統(tǒng)調(diào)用會(huì)將數(shù)據(jù)寫到內(nèi)存中的 page cache，將 page 標(biāo)記為 臟頁(dirty) 后返回。
linux 的 writeback 機(jī)制
對于將內(nèi)存緩沖區(qū)的內(nèi)容刷到磁盤上，則有兩種方式：
首先，應(yīng)用程序在調(diào)用 write 系統(tǒng)調(diào)用寫入數(shù)據(jù)時(shí)，如果發(fā)現(xiàn) page cache 的使用量大于了設(shè)定的大小，便會(huì)主動(dòng)將內(nèi)存中的臟頁刷到硬盤上。在此期間，所有的 write 系統(tǒng)調(diào)用都會(huì)被阻塞。
系統(tǒng)當(dāng)然不會(huì)容忍不定時(shí)的 write 阻塞，linux 還會(huì)定時(shí)啟動(dòng) pdflush 線程，判斷內(nèi)存頁達(dá)到一定的比例或臟頁存活時(shí)間達(dá)到設(shè)定的時(shí)間，將這些臟頁刷回到磁盤上，以避免被動(dòng)刷緩沖區(qū)，這種機(jī)制就是 linux 的 writeback 機(jī)制。
猜測
了解了以上基礎(chǔ)知識，那么對于 write 系統(tǒng)調(diào)用為什么會(huì)被阻塞，提出了兩種可能：
- page cache 可用空間不足，導(dǎo)致觸發(fā)了主動(dòng)的 flush，此時(shí)會(huì)阻塞所有對此 device 的 write。
- 寫入過程被其他事務(wù)阻塞。
首先對于第一種可能： 查看系統(tǒng)配置?dirty_ratio?的大小： 20。此值是 page cache 占用系統(tǒng)可用內(nèi)存(real mem + swap)的最大百分比， 我們的內(nèi)存為 32G，沒有啟用 swap，則實(shí)際可用的 page cache 大小約為 6G。
另外，與 pdflush 相關(guān)的系統(tǒng)配置：系統(tǒng)會(huì)每?vm.dirty_writeback_centisecs?(5s) 喚醒一次 pdflush 線程， 發(fā)現(xiàn)臟頁比例超過?vm.dirty_background_ratio?(10%) 或 臟頁存活時(shí)間超過?vm.dirty_expire_centisecs(30s) 時(shí)，會(huì)將臟頁刷回硬盤。
查看?/proc/meminfo?內(nèi)?Dirty/Writeback?項(xiàng)的變化，并對比服務(wù)的文件寫入速度，結(jié)論是數(shù)據(jù)會(huì)被 pdflush 刷回到硬盤，不會(huì)觸發(fā)被動(dòng) flush 以阻塞 write 系統(tǒng)調(diào)用。
ext4 的 journal 特性
write 被阻塞的原因
繼續(xù)搜索資料，在一篇文章(Why buffered writes are sometimes stalled?)中看到 write 系統(tǒng)調(diào)用被阻塞有以下可能：
- 要寫入的數(shù)據(jù)依賴讀取的結(jié)果時(shí)。但記錄日志不依賴讀文件；
- wirte page 時(shí)有別的線程在調(diào)用 fsync() 等主動(dòng) flush 臟頁的方法。但由于鎖的存在，log 在寫入時(shí)不會(huì)有其他的線程操作；
- 格式為 ext3/4 的文件系統(tǒng)在記錄 journal log 時(shí)會(huì)阻塞 write。而我們的系統(tǒng)文件格式為 ext4。維基百科上的一個(gè)條目（ https://en.wikipedia.org/wiki/Journaling_block_device ） 也描述了這種可能。
journal
journal 是 文件系統(tǒng)保證數(shù)據(jù)一致性的一種手段，在寫入數(shù)據(jù)前，將即將進(jìn)行的各個(gè)操作步驟記錄下來，一旦系統(tǒng)掉電，恢復(fù)時(shí)讀取這些日志繼續(xù)操作就可以了。但批量的 journal commit 是一個(gè)事務(wù)，flush 時(shí)會(huì)阻塞 write 的提交。
我們可以使用?dumpe2fs /dev/disk | grep features?查看磁盤支持的特性，其中有?has_journal?代表文件系統(tǒng)支持 journal 特性。
ext4 格式的文件系統(tǒng)在掛載時(shí)可以選擇 (jouranling、ordered、writeback) 三種之一的 journal 記錄模式。
三種模式分別有以下特性：
- journal： 在將數(shù)據(jù)寫入文件系統(tǒng)前，必須等待 metadata 和 journal 已經(jīng)落盤了。
- ordered： 不記錄數(shù)據(jù)的 journal，只記錄 metadata 的 journal 日志，且需要保證所有數(shù)據(jù)在其 metadata journal 被 commit 之前落盤。 ext4 在不添加掛載參數(shù)時(shí)使用此模式。
- writeback: 數(shù)據(jù)可能在 metadata journal 被提交之后落盤，可能導(dǎo)致舊數(shù)據(jù)在系統(tǒng)掉電后恢復(fù)到磁盤中。
當(dāng)然，我們也可以選擇直接禁用 journal，使用?tune2fs -O ^has_journal /dev/disk，只能操作未被掛載的磁盤。
猜測因?yàn)?journal 觸發(fā)了臟頁落盤，而臟頁落盤導(dǎo)致 write 被阻塞，所以解決 journal 問題就可以解決接口超時(shí)問題。
解決方案與壓測結(jié)果
以下是我總結(jié)的幾個(gè)接口超時(shí)問題的解決方案：
- log4j2 日志模式改異步。但有可能會(huì)在系統(tǒng)重啟時(shí)丟失日志，另外在異步隊(duì)列 ringbuffer 被填滿未消費(fèi)后，新日志會(huì)自動(dòng)使用同步模式。
- 調(diào)整系統(tǒng)刷臟頁的配置，將檢查臟頁和臟頁過期時(shí)間設(shè)置得更短(1s 以內(nèi))。但理論上會(huì)略微提升系統(tǒng)負(fù)載（未明顯觀察到）。
- 掛載硬盤時(shí)使用 data=writeback 選項(xiàng)修改 journal 模式。 但可能導(dǎo)致系統(tǒng)重啟后文件包含已刪除的內(nèi)容。
- 禁用 ext4 的 journal 特性。但可能會(huì)導(dǎo)致系統(tǒng)文件的不一致。
- 把 ext4 的 journal 日志遷移到更快的磁盤上，如 ssd、閃存等。操作復(fù)雜，不易維護(hù)。
- 使用 xfs、fat 等 文件系統(tǒng)格式。特性不了解，影響不可知。
當(dāng)然，對于這幾種方案，我也做了壓測，以下是壓測的結(jié)果。
?
| ? | 文件系統(tǒng)特性 | 接口超時(shí)比例 |
|---|---|---|
| ? | ext4（同線上） | 0.202% |
| ? | xfs文件系統(tǒng) | 0.06% |
| ? | page過期時(shí)間和pdflush啟動(dòng)時(shí)間都設(shè)置為 0.8s | 0.017% |
| ? | ext4 掛載時(shí) journal 模式為 writeback | 0% |
| ? | 禁用 ext4 的 journal 特性 | 0% |
| ? | log4j2 使用異步日志 | 0% |
小結(jié)
接口超時(shí)問題總算是告一段落，查了很久，不過解決它之后也非常有成就感。遺憾的是沒有在 linux 內(nèi)核代碼中找到證據(jù)，160M 的代碼，分層也不熟悉，實(shí)在是無從查起，希望以后有機(jī)會(huì)能慢慢接觸吧。
程序員還是要懂些操作系統(tǒng)知識的，不僅幫我們在應(yīng)對這種詭異的問題時(shí)不至于束手無策，也可以在做一些業(yè)務(wù)設(shè)計(jì)時(shí)能有所參考。
又熟悉了一些系統(tǒng)工具和命令，腳手架上又豐富了。
關(guān)于本文有什么疑問可以在下面留言交流，如果您覺得本文對您有幫助，歡迎關(guān)注我的?微博?或?GitHub?。您也可以在我的?博客REPO?右上角點(diǎn)擊?Watch?并選擇?Releases only?項(xiàng)來?訂閱?我的博客，有新文章發(fā)布會(huì)第一時(shí)間通知您。
轉(zhuǎn)載于:https://www.cnblogs.com/zhenbianshu/p/10186899.html
總結(jié)
以上是生活随笔為你收集整理的从应用到内核查接口超时（中）的全部內(nèi)容，希望文章能夠幫你解決所遇到的問題。
