太難了，一個(gè)接口超時(shí)問題，從應(yīng)用排查到內(nèi)核....

問題描述

最近在查一個(gè)問題，花費(fèi)了近兩個(gè)星期，問題算是有了一個(gè)小結(jié)，是時(shí)候總結(jié)一下了。

排查過程走了很多彎路，由于眼界和知識(shí)儲(chǔ)備問題，也進(jìn)入了一些思維誤區(qū)，希望此問題能以后再查詢此類問題時(shí)能有所警示和參考。

而且很多排查方法和思路都來(lái)自于部門 leader 和 組里大神給的提示和啟發(fā)，總結(jié)一下也能對(duì)這些知識(shí)有更深的理解。

這個(gè)問題出現(xiàn)在典型的高并發(fā)場(chǎng)景下，現(xiàn)象是某個(gè)接口會(huì)偶爾超時(shí)。

查了幾個(gè) case 的日志，發(fā)現(xiàn) httpClient 在請(qǐng)求某三方接口結(jié)束后輸出一條日志時(shí)間為 A，方法返回后將請(qǐng)求結(jié)果解析成為 JSON 對(duì)象后，再輸出的日志時(shí)間為 B， AB之間的時(shí)間差會(huì)特別大，100-700ms 不等，而 JSON 解析正常是特別快的，不應(yīng)該超過 1ms。

GC

首先考慮導(dǎo)致這種現(xiàn)象的可能：

• 應(yīng)用上有鎖導(dǎo)致方法被 block 住了，但 JSON 解析方法上并不存在鎖，排除這種可能。

• JVM 上，GC 可能導(dǎo)致 STW。

• 系統(tǒng)上，如果系統(tǒng)負(fù)載很高，操作系統(tǒng)繁忙，線程調(diào)度出現(xiàn)問題可能會(huì)導(dǎo)致這種情況，但觀察監(jiān)控系統(tǒng)發(fā)現(xiàn)系統(tǒng)負(fù)載一直處于很低的水平，也排除了系統(tǒng)問題。

我們都知道 JVM 在 GC 時(shí)會(huì)導(dǎo)致 STW，進(jìn)而導(dǎo)致所有線程都會(huì)暫停，接下來(lái)重點(diǎn)排查 GC 問題。

首先我們使用 jstat 命令查看了 GC 狀態(tài)，發(fā)現(xiàn) fullGC 并不頻繁，系統(tǒng)運(yùn)行了兩天才有 100 來(lái)次，而 minorGC 也是幾秒才會(huì)進(jìn)行一次，且 gcTime 一直在正常范圍。

由于我們的 JVM 在啟動(dòng)時(shí)添加了 -XX:+PrintGCApplicationStoppedTime 參數(shù)，而這個(gè)參數(shù)的名字跟它的意義并不是完全相對(duì)的，在啟用此參數(shù)時(shí)，gclog 不僅會(huì)打印出 GC 導(dǎo)致的 STW，其他原因?qū)е碌?STW 也會(huì)被記錄到 gclog 中，于是 gclog 就可以成為一個(gè)重要的排查工具。

查看 gclog 發(fā)現(xiàn)確實(shí)存在異常狀況，如下圖：

系統(tǒng) STW 有時(shí)會(huì)非常頻繁地發(fā)生，且持續(xù)時(shí)間也較長(zhǎng)，其中間隔甚至不足 1ms。

也就是說(shuō)一次停頓持續(xù)了幾十 ms 之后，系統(tǒng)還沒有開始運(yùn)行，又會(huì)進(jìn)行第二次 STW，如上圖的情況，系統(tǒng)應(yīng)該會(huì)一次 hang 住 120ms，如果次數(shù)再頻繁一些，確實(shí)有可能會(huì)導(dǎo)致接口超時(shí)。

安全點(diǎn)

那么這么頻繁的 STW 是由什么產(chǎn)生的呢，minorGC 的頻率都沒有這么高。

我們知道，系統(tǒng)在 STW 前，會(huì)等待所有線程安全點(diǎn)，在安全點(diǎn)里，線程的狀態(tài)是確定的，其引用的 heap 也是靜止的，這樣，JVM 才能安心地進(jìn)行 GC 等操作。

至于安全點(diǎn)的常見位置和安全點(diǎn)的實(shí)現(xiàn)方式網(wǎng)卡有很多文章介紹這里不再多提了，這里重點(diǎn)說(shuō)一下安全點(diǎn)日志。

安全點(diǎn)日志是每次 JVM 在所有線程進(jìn)入安全點(diǎn) STW 后輸出的日志，日志記錄了進(jìn)入安全點(diǎn)用了多久，STW 了多久，安全點(diǎn)內(nèi)的時(shí)間都是被哪個(gè)步驟消耗的，通過它我們可以分析出 JVM STW 的原因。

服務(wù)啟動(dòng)時(shí)，使用?-XX:+UnlockDiagnosticVMOptions -XX:+PrintSafepointStatistics -XX:+LogVMOutput -XX:LogFile=./safepoint.log?參數(shù)，可以將安全點(diǎn)日志輸出到 safepoint.log 中。

在安全點(diǎn)日志中，我發(fā)現(xiàn)有很多下圖類似的日志輸出：

從前面的 vmopt 列可以得知，進(jìn)入安全點(diǎn)的原因是 RevokeBias， 查資料得知，這是在釋放 偏向鎖。

偏向鎖

偏向鎖是 JVM 對(duì)鎖的一種優(yōu)化，JVM 的開發(fā)人員統(tǒng)計(jì)發(fā)現(xiàn)絕大部分的鎖都是由同一個(gè)線程獲取，鎖爭(zhēng)搶的可能性很小，而系統(tǒng)調(diào)用一次加鎖釋放鎖的開銷相對(duì)很大，所以引入偏向鎖默認(rèn)鎖不會(huì)被競(jìng)爭(zhēng)，偏向鎖中的 “偏向” 便指向第一個(gè)獲取到鎖的線程。

在一個(gè)鎖在被第一次獲取后，JVM 并不需要用系統(tǒng)指令加鎖，而是使用偏向鎖來(lái)標(biāo)志它，將對(duì)象頭中 MarkWord 的偏向鎖標(biāo)識(shí)設(shè)置為1，將偏向線程設(shè)置為持續(xù)鎖的線程 ID，這樣，之后線程再次申請(qǐng)鎖時(shí)如果發(fā)現(xiàn)這個(gè)鎖已經(jīng) “偏向” 了當(dāng)前線程，直接使用即可。

而且持有偏向鎖的線程不會(huì)主動(dòng)釋放鎖，只有在出現(xiàn)鎖競(jìng)爭(zhēng)時(shí)，偏向鎖才會(huì)釋放，進(jìn)而膨脹為更高級(jí)別的鎖。

有利則有弊，偏向鎖在單線程環(huán)境內(nèi)確實(shí)能極大降低鎖消耗，但在多線程高并發(fā)環(huán)境下，線程競(jìng)爭(zhēng)頻繁，而偏向鎖在釋放時(shí)，為了避免出現(xiàn)沖突，需要等到進(jìn)入全局安全點(diǎn)才能進(jìn)行，所以每次偏向鎖釋放會(huì)有更大的消耗。

明白了 JVM 為什么會(huì)頻繁進(jìn)行 STW，再修改服務(wù)啟動(dòng)參數(shù)，添加?-XX:-UseBiasedLocking?參數(shù)禁用偏向鎖后，再觀察服務(wù)運(yùn)行。

發(fā)現(xiàn)停頓問題的頻率下降了一半，但還是會(huì)出現(xiàn)，問題又回到原點(diǎn)。

Log4j

定位

這時(shí)候就需要猜想排查了。

首先提出可能導(dǎo)致問題的點(diǎn)，再依次替換掉這些因素壓測(cè)，看能否復(fù)現(xiàn)來(lái)確定問題點(diǎn)。

考慮到的問題點(diǎn)有 HttpClient、Hystrix、Log4j2。

使用固定數(shù)據(jù)替換了三方接口的返回值，刪去了 Hystrix，甚至將邏輯代碼都刪掉，只要使用 Log4j2 輸出大量日志，問題就可以復(fù)現(xiàn)，終于定位到了 Log4j2，原來(lái)是監(jiān)守自盜啊...

雖然定位到 Log4j2，但日志也不能不記啊，還是要查問題到底出在哪里。

使用 btrace 排查 log4j2 內(nèi)的鎖性能。

首先考慮 Log4j2 代碼里的鎖，懷疑是由于鎖沖突，導(dǎo)致輸出 log 時(shí)被 block 住了。

查看源碼，統(tǒng)計(jì)存在鎖的地方有三處：

• rollover() 方法，在檢測(cè)到日志文件需要切換時(shí)會(huì)鎖住進(jìn)行日志文件的切分。

• encodeText() 方法，日志輸出需要將各種字符集的日志都轉(zhuǎn)換為 byte 數(shù)組，在進(jìn)行大日志輸出時(shí)，需要分塊進(jìn)行。為了避免多線程塊之間的亂序，使用synchronized 關(guān)鍵字對(duì)方法加鎖。

• flush() 方法，同樣是為了避免不同日志之間的穿插亂序，需要對(duì)此方法加鎖。

具體是哪一處代碼出現(xiàn)了問題呢，我使用 btrace 這一 Java 性能排查利器進(jìn)行了排查。

使用 btrace 分別在這三個(gè)方法前后都注入代碼，將方法每次的執(zhí)行時(shí)間輸出，然后進(jìn)行壓測(cè)，等待問題發(fā)生，最終找到了執(zhí)行慢的方法:encodeText()。

排查代碼并未發(fā)現(xiàn) encodeText 方法的異常（千錘百煉的代碼，當(dāng)然看不出什么問題）。

使用 jmc 分析問題

這時(shí)，組內(nèi)大神建議我使用 jmc 來(lái)捕捉異常事件。給 docker-compose 添加以下參數(shù)來(lái)啟用環(huán)境的 JFR。

environment:??
???-?JFR=true??
???-?JMX_PORT=port??
???-?JMX_HOST=ip??
???-?JMX_LOGIN=user:pwd??

在記錄內(nèi)查找停頓時(shí)間附近的異常事件，發(fā)現(xiàn)耗時(shí)統(tǒng)計(jì)內(nèi)有一項(xiàng)長(zhǎng)耗時(shí)引人注目：調(diào)用 RandomAccessFile.write() 方法竟然耗時(shí) 1063 ms，而這個(gè)時(shí)間段和線程 ID 則完全匹配。

查看這個(gè)耗時(shí)長(zhǎng)的方法，它調(diào)用的是 native 方法 write()...

階段性小結(jié)

native 方法再查下去就是系統(tǒng)問題了，但是目前我們可以給出兩個(gè)對(duì)癥下藥的解決方案。

• 服務(wù)少記一些日志，日志太多的話才會(huì)導(dǎo)致這個(gè)問題。

• 使用 Log4j2 的異步日志，雖然有可能會(huì)在緩沖區(qū)滿或服務(wù)重啟時(shí)丟日志。

同時(shí)可以進(jìn)行一個(gè)階段性的小結(jié)。

查問題的過程確實(shí)學(xué)習(xí)到了很多知識(shí)，讓我更熟悉了 Java 的生態(tài)，但我覺得更重要的是排查問題的思路，于是我總結(jié)了一個(gè)排查問題的一般步驟，當(dāng)作以后排查此類問題的 checkList。

• 盡量分析更多的問題 case。找出他們的共性，避免盯錯(cuò)問題點(diǎn)。比如此次問題排查開始時(shí)，如果多看幾個(gè) case 就會(huì)發(fā)現(xiàn)，日志停頓在任何日志點(diǎn)都會(huì)出現(xiàn)，由此就可以直接排除掉 HttpClient 和 Hystrix 的影響。

• 在可控的環(huán)境復(fù)現(xiàn)問題。在測(cè)試環(huán)境復(fù)現(xiàn)問題可能幫助我們隨時(shí)調(diào)整排查策略，極大地縮短排查周期。當(dāng)然還需要注意的是一定要跟線上環(huán)境保持一致，不一致的環(huán)境很可能把你的思路帶歪，比如我在壓測(cè)復(fù)現(xiàn)問題時(shí)，由于堆內(nèi)存設(shè)置得太小，導(dǎo)致頻繁發(fā)生 GC，讓我錯(cuò)認(rèn)為是 GC 原因?qū)е碌耐ｎD。

• 對(duì)比變化，提出猜想。在服務(wù)出現(xiàn)問題時(shí)，我們總是先問最近上線了什么內(nèi)容，程序是有慣性的，如果沒有變化，系統(tǒng)一般會(huì)一直正常運(yùn)行。當(dāng)然變化不止是時(shí)間維度上的，我們還可以在多個(gè)服務(wù)之間對(duì)比差異。

• 排除法定位問題。一般我們會(huì)提出多個(gè)導(dǎo)致問題的可能性，排查時(shí)，保持一個(gè)變量在變化，再對(duì)比問題的發(fā)生，從而總結(jié)出變量對(duì)問題的影響。解決。當(dāng)我們定位到問題之后，問題的解決一般都很簡(jiǎn)單，可能只需要改一行代碼。

當(dāng)然還有一個(gè)非常重要的點(diǎn)，貫穿始末，那就是數(shù)據(jù)支持，排查過程中一定要有數(shù)據(jù)作為支持。通過總量、百分比數(shù)據(jù)的前后對(duì)比來(lái)說(shuō)服其他人相信你的理論，也就是用數(shù)據(jù)說(shuō)話。

應(yīng)用復(fù)現(xiàn)

Jdk 的 native 方法當(dāng)然不是終點(diǎn)，雖然發(fā)現(xiàn) Jdk、docker、操作系統(tǒng) Bug 的可能性極小，但再往底層查卻很可能發(fā)現(xiàn)一些常見的配置錯(cuò)誤。

為了便于復(fù)現(xiàn)，我用 JMH 寫了一個(gè)簡(jiǎn)單的 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)都能很簡(jiǎn)單地復(fù)現(xiàn)日志停頓問題。而 jdk 版本眾多，我準(zhǔn)備首先排查操作系統(tǒng)配置問題。

系統(tǒng)調(diào)用

這里需要使用到 strace 命令。

這個(gè)命令很早就使用過，但我還是不太習(xí)慣把 Java 和它聯(lián)系起來(lái)，幸好有部門的老司機(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)用。

對(duì)比 jmh 壓測(cè)用例輸出的 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)的知識(shí)了。

在 linux 系統(tǒng)中，萬(wàn)物皆文件，而為了給不同的介質(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ù)量級(jí)上，為了平衡兩者之間的速度，linux 便把文件映射到內(nèi)存中，將硬盤單位塊(block)對(duì)應(yīng)到內(nèi)存中的一個(gè) 頁(yè)(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)記為 臟頁(yè)(dirty) 后返回。

linux 的 writeback 機(jī)制

對(duì)于將內(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)存中的臟頁(yè)刷到硬盤上。在此期間，所有的 write 系統(tǒng)調(diào)用都會(huì)被阻塞。

系統(tǒng)當(dāng)然不會(huì)容忍不定時(shí)的 write 阻塞，linux 還會(huì)定時(shí)啟動(dòng) pdflush 線程，判斷內(nèi)存頁(yè)達(dá)到一定的比例或臟頁(yè)存活時(shí)間達(dá)到設(shè)定的時(shí)間，將這些臟頁(yè)刷回到磁盤上，以避免被動(dòng)刷緩沖區(qū)，這種機(jī)制就是 linux 的 writeback 機(jī)制。

猜測(cè)

了解了以上基礎(chǔ)知識(shí)，那么對(duì)于 write 系統(tǒng)調(diào)用為什么會(huì)被阻塞，提出了兩種可能：

• page cache 可用空間不足，導(dǎo)致觸發(fā)了主動(dòng)的 flush，此時(shí)會(huì)阻塞所有對(duì)此 device 的 write。

• 寫入過程被其他事務(wù)阻塞。

首先對(duì)于第一種可能。查看系統(tǒng)配置 dirty_ratio 的大?。?0。

此值是 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)臟頁(yè)比例超過?vm.dirty_background_ratio?(10%) 或 臟頁(yè)存活時(shí)間超過?vm.dirty_expire_centisecs(30s) 時(shí)，會(huì)將臟頁(yè)刷回硬盤。

查看 /proc/meminfo 內(nèi) Dirty/Writeback 項(xiàng)的變化，并對(duì)比服務(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)用被阻塞有以下可能：

http://yoshinorimatsunobu.blogspot.com/2014/03/why-buffered-writes-are-sometimes.html

• 要寫入的數(shù)據(jù)依賴讀取的結(jié)果時(shí)。但記錄日志不依賴讀文件；

• wirte page 時(shí)有別的線程在調(diào)用 fsync() 等主動(dòng) flush 臟頁(yè)的方法。但由于鎖的存在，log 在寫入時(shí)不會(huì)有其他的線程操作；

• 格式為 ext3/4 的文件系統(tǒng)在記錄 journal log 時(shí)會(huì)阻塞 write。而我們的系統(tǒng)文件格式為 ext4。

journal

journal 是 文件系統(tǒng)保證數(shù)據(jù)一致性的一種手段，在寫入數(shù)據(jù)前，將即將進(jìn)行的各個(gè)操作步驟記錄下來(lái)，一旦系統(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，只能操作未被掛載的磁盤。

猜測(cè)因?yàn)?journal 觸發(fā)了臟頁(yè)落盤，而臟頁(yè)落盤導(dǎo)致 write 被阻塞，所以解決 journal 問題就可以解決接口超時(shí)問題。

解決方案與壓測(cè)結(jié)果

以下是我總結(jié)的幾個(gè)接口超時(shí)問題的解決方案：

• log4j2 日志模式改異步。但有可能會(huì)在系統(tǒng)重啟時(shí)丟失日志，另外在異步隊(duì)列 ringbuffer 被填滿未消費(fèi)后，新日志會(huì)自動(dòng)使用同步模式。

• 調(diào)整系統(tǒng)刷臟頁(yè)的配置，將檢查臟頁(yè)和臟頁(yè)過期時(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)然，對(duì)于這幾種方案，我也做了壓測(cè)，以下是壓測(cè)的結(jié)果：

所以，程序員還是要懂些操作系統(tǒng)知識(shí)的，不僅幫我們?cè)趹?yīng)對(duì)這種詭異的問題時(shí)不至于束手無(wú)策，也可以在做一些業(yè)務(wù)設(shè)計(jì)時(shí)能有所參考。

打印進(jìn)程內(nèi)核棧

前面我們查到是因?yàn)?journal 導(dǎo)致 write 系統(tǒng)調(diào)用被阻塞進(jìn)而導(dǎo)致超時(shí)，但是總感覺證據(jù)還不夠充分，沒有一個(gè)完美的交待。

所以我們還需要繼續(xù)追蹤問題。

回到問題的原點(diǎn)，對(duì)于此問題，我能確定的資料只有穩(wěn)定復(fù)現(xiàn)的環(huán)境和不知道什么時(shí)候會(huì)觸發(fā) write system call 延遲的 jar 包。

考慮到 write system call 被阻塞可長(zhǎng)達(dá)幾百 ms，我想我能抓出當(dāng)前進(jìn)程的內(nèi)核棧來(lái)看一下 write system call 此時(shí)被阻塞在什么位置。

具體步驟為：

• 多個(gè)線程不便于抓內(nèi)核棧，先將程序修改為單線程定量寫入。

• 使用 jar 包啟動(dòng)一個(gè)進(jìn)程，使用 ps 拿到進(jìn)程號(hào)。

• 再通過 top -H -p pid 拿到占用 cpu、內(nèi)存等資源最多的線程 ID，或使用 strace 啟動(dòng)，查看其輸出里正在寫入的線程 ID。

• 使用 watch 命令搭配 pstack 或 cat /proc/pid/stack 不停打印進(jìn)程內(nèi)核棧。具體命令為 watch -n 0.1 "date +%s >> stack.log;cat /proc/pid/stack >> stack.log"

• 找到 write system call 被阻塞時(shí)的時(shí)間戳，在 stack.log 里查看當(dāng)時(shí)的進(jìn)程內(nèi)核棧。

可穩(wěn)定收集到 write system call 被阻塞時(shí)，進(jìn)程內(nèi)核棧為：

?[]?call_rwsem_down_read_failed+0x14/0x30??
?[]?ext4_da_get_block_prep+0x1a4/0x4b0?[ext4]??
?[]?__block_write_begin+0x1a7/0x490??
?[]?ext4_da_write_begin+0x15c/0x340?[ext4]??
?[]?generic_file_buffered_write+0x11e/0x290??
?[]?__generic_file_aio_write+0x1d5/0x3e0??
?[]?generic_file_aio_write+0x5d/0xc0??
?[]?ext4_file_write+0xb5/0x460?[ext4]??
?[]?do_sync_write+0x8d/0xd0??
?[]?vfs_write+0xbd/0x1e0??
?[]?SyS_write+0x58/0xb0??
?[]?system_call_fastpath+0x16/0x1b??
?[]?0xffffffffffffffff

內(nèi)核棧分析

write system call 阻塞位置

通過內(nèi)核棧函數(shù)關(guān)鍵字找到了 OenHan 大神的博客：讀寫信號(hào)量與實(shí)時(shí)進(jìn)程阻塞掛死問題。

https://oenhan.com/rwsem-realtime-task-hung

這篇文章描述的問題雖然跟我遇到的問題不同，但進(jìn)程內(nèi)核棧的分析對(duì)我很有啟發(fā)。為了便于分析內(nèi)核函數(shù)，我 clone 了一份 linux 3.10.0 的源碼，在本地查看。

搜索源碼可以證實(shí)，棧頂?shù)膮R編函數(shù)?ENTRY call_rwsem_down_read_failed?會(huì)調(diào)用?rwsem_down_read_failed(), 而此函數(shù)會(huì)一直阻塞在獲取 inode 的鎖。

struct?rw_semaphore?__sched?*rwsem_down_read_failed(struct?rw_semaphore?*sem)?{??
????????.....??
?/*?wait?to?be?given?the?lock?*/??
?while?(true)?{??
??set_task_state(tsk,?TASK_UNINTERRUPTIBLE);??
??if?(!waiter.task)??
???break;??
??schedule();??
?}??
??
?tsk->state?=?TASK_RUNNING;??
??
?return?sem;??
}??

延遲分配

知道了 write system call 阻塞的位置，還要查它會(huì)什么會(huì)阻塞在這里。

這時(shí)，棧頂?shù)暮瘮?shù)名?call_rwsem_down_read_failed?讓我覺得很奇怪，這不是 “write” system call 么，為什么會(huì)?down_read_failed？

直接搜索這個(gè)函數(shù)沒有什么資料，但向棧底方向，再搜索其他函數(shù)就有了線索了，原來(lái)這是在做系統(tǒng)磁盤塊的準(zhǔn)備，于是就牽扯出了 ext4 的 delayed allocation 特性。

延遲分配(delayed allocation)：ext4 文件系統(tǒng)在應(yīng)用程序調(diào)用 write system call 時(shí)并不為緩存頁(yè)面分配對(duì)應(yīng)的物理磁盤塊，當(dāng)文件的緩存頁(yè)面真正要被刷新至磁盤中時(shí)，才會(huì)為所有未分配物理磁盤塊的頁(yè)面緩存分配盡量連續(xù)的磁盤塊。

這一特性，可以避免磁盤的碎片化，也可以避免存活時(shí)間極短文件的磁盤塊分配，能很大提升系統(tǒng)文件 I/O 性能。

而在 write 向內(nèi)存頁(yè)時(shí)，就需要查詢這些內(nèi)存頁(yè)是否已經(jīng)分配了磁盤塊，然后給未分配的臟頁(yè)打上延遲分配的標(biāo)簽。

寫入的詳細(xì)過程可以查看 ext4 的延遲分配：

https://blog.csdn.net/kai_ding/article/details/9914629

此時(shí)需要獲取此 inode 的讀鎖，若出現(xiàn)鎖沖突，write system call 便會(huì) hang 住。

在掛載磁盤時(shí)使用 -o nodelalloc 選項(xiàng)禁用掉延遲分配特性后再進(jìn)行測(cè)試，發(fā)現(xiàn) write system call 被阻塞的情況確實(shí)消失了，證明問題確定跟延遲分配有關(guān)。

不算結(jié)論的結(jié)論

尋找寫鎖

知道了 write system call 阻塞在獲取讀鎖，那么一定是內(nèi)核里有哪些地方持有了寫鎖。

ipcs 命令可以查看系統(tǒng)內(nèi)核此時(shí)的進(jìn)程間通信設(shè)施的狀態(tài)，它打印的項(xiàng)目包括消息列表(-q)、共享內(nèi)存(-m)和信號(hào)量(-q)的信息，用 ipcs -q 打印內(nèi)核棧的函數(shù)查看 write system call 被阻塞時(shí)的信號(hào)量，卻沒有輸出任何信息。

仔細(xì)想了一下發(fā)現(xiàn)其寫鎖 i_data_sem 是一把讀寫鎖，而信號(hào)量是一種 非0即1 的PV量，雖然名字里帶有 sem，可它并不是用信號(hào)量實(shí)現(xiàn)的。

perf lock 可以用來(lái)分析系統(tǒng)內(nèi)核的鎖信息，但要使用它需要重新編譯內(nèi)核，添加 CONFIG_LOCKDEP、CONFIG_LOCK_STAT 選項(xiàng)。先不說(shuō)我們測(cè)試機(jī)的重啟需要建提案等兩天，編譯完能不能啟動(dòng)得來(lái)我真的沒有信心，第一次試圖使用 perf 分析 linux 性能問題就這么折戟了。

轉(zhuǎn)變方法

問題又卡住了，這時(shí)我也沒有太多辦法了，現(xiàn)在開始研究 linux 文件系統(tǒng)源碼是來(lái)不及了，但我還可以問。

在 stackOverflow 上問沒人理我：how metadata journal stalls write system call?，

https://stackoverflow.com/questions/52778498/how-metadata-journal-stalls-write-system-call

追著 OenHan 問了幾次也沒有什么結(jié)論：Linux內(nèi)核寫文件流程。

http://oenhan.com/linux-kernel-write#comment-201

雖然自己沒法測(cè)試 upstream linux，還是在 kernel bugzilla 上發(fā)了個(gè)帖子：ext4 journal stalls write system call。

https://bugzilla.kernel.org/show_bug.cgi?id=201461

終于有內(nèi)核大佬回復(fù)我：在 ext4_map_blocks() 函數(shù)中進(jìn)行磁盤塊分配時(shí)內(nèi)核會(huì)持有寫鎖。

查看了源碼里的函數(shù)詳情，證實(shí)了這一結(jié)論：

/*??
?*?The?ext4_map_blocks()?function?tries?to?look?up?the?requested?blocks,??
?*?and?returns?if?the?blocks?are?already?mapped.??
?*??
?*?Otherwise?it?takes?the?write?lock?of?the?i_data_sem?and?allocate?blocks??
?*?and?store?the?allocated?blocks?in?the?result?buffer?head?and?mark?it??
?*?mapped.??
*/??
int?ext4_map_blocks(handle_t?*handle,?struct?inode?*inode,??
??????struct?ext4_map_blocks?*map,?int?flags)??
{??
.....??
?/*??
??*?New?blocks?allocate?and/or?writing?to?uninitialized?extent??
??*?will?possibly?result?in?updating?i_data,?so?we?take??
??*?the?write?lock?of?i_data_sem,?and?call?get_blocks()??
??*?with?create?==?1?flag.??
??*/??
?down_write((&EXT4_I(inode)->i_data_sem));??
.....??
}??

但又是哪里引用了 ext4_map_blocks() 函數(shù)，長(zhǎng)時(shí)間獲取了寫鎖呢？

再追問時(shí)大佬已經(jīng)頗有些無(wú)奈了，linux 3.10.0 的 release 已經(jīng)是 5年 前了，當(dāng)時(shí)肯定也有一堆 bug 和缺陷，到現(xiàn)在已經(jīng)發(fā)生了很大變動(dòng)，追查這個(gè)問題可能并沒有很大的意義了，我只好識(shí)趣停止了。

推論

其實(shí)再向下查這個(gè)問題對(duì)我來(lái)說(shuō)也沒有太大意義了，缺少對(duì)源碼理解的積累，再看太多的資料也沒有什么收益。

就如向建筑師向小孩子講建筑設(shè)計(jì)，知道窗子要朝南，大門要靠近電梯這些知識(shí)并無(wú)意義，不了解建筑設(shè)計(jì)的原則，只專注于一些自己可以推導(dǎo)出來(lái)的理論點(diǎn)，根本沒辦法吸收到其中精髓。

那么只好走到最后一步，根據(jù)查到的資料和測(cè)試現(xiàn)象對(duì)問題原因做出推論，雖然沒有直接證據(jù)，但肯定跟這些因素有關(guān)。

在 ext4 文件系統(tǒng)下，默認(rèn)為 ordered journal 模式，所以寫 metadata journal 可能會(huì)迫使臟頁(yè)刷盤， 而在 ext4 啟用 delayed allocation 特性時(shí)，臟頁(yè)可能在落盤時(shí)發(fā)現(xiàn)沒有分配對(duì)應(yīng)的磁盤塊而分配磁盤塊。在臟頁(yè)太多的情況下，分配磁盤塊慢時(shí)會(huì)持有 inode 的寫鎖時(shí)間過長(zhǎng)，阻塞了 write 系統(tǒng)調(diào)用。

追求知識(shí)的每一步或多或少都有其中意義，查這個(gè)問題就迫使我讀了很多外語(yǔ)文獻(xiàn)，也了解了一部分文件系統(tǒng)設(shè)計(jì)思想。

linux 真的是博大精深啊。