從應用到內核查接口超時（下）

再啓

---

接上文 從應用到內核查接口超時（中），查到是由於 journal 致使 write 系統調用被阻塞進而致使超時後，總感受證據還不夠充分，沒有一個完美的交待。並且 leader 還想着讓我把問題排查過程分享給同事們，這讓我更加不安，擔憂搞錯了方向。

在以往的博客中，個人問題結論老是肯定的，若是是推論的話，我會顯式註明。如今的狀況讓我有點犯難，推論說出去擔憂誤導了別人，而內核層的事，我只知道基本理論，有關此問題的結論尚未。

因而，我只好再次踏上查這個問題的征程。

轉載隨意，文章會持續修訂，請註明來源地址：https://zhenbianshu.github.io 。

打印進程內核棧

---

回到問題的原點，對於此問題，我能肯定的資料只有穩定復現的環境和不知道何時會觸發 write system call 延遲的 jar 包。

考慮到 write system call 被阻塞可長達幾百 ms，我想我能抓出當前進程的內核棧來看一下 write system call 此時被阻塞在什麼位置。

具體步驟爲：

1. 多個線程不便於抓內核棧，先將程序修改成單線程定量寫入。
2. 使用 jar 包啓動一個進程，使用 ps 拿到進程號。
3. 再經過 top -H -p pid 拿到佔用 cpu、內存等資源最多的線程 ID，或使用 strace 啓動，查看其輸出里正在寫入的線程 ID。
4. 使用 watch 命令搭配 pstack 或 cat /proc/pid/stack 不停打印進程內核棧。具體命令爲 watch -n 0.1 "date +%s >> stack.log;cat /proc/pid/stack >> stack.log"
5. 找到 write system call 被阻塞時的時間戳，在 stack.log 裏查看當時的進程內核棧。

可穩定收集到 write system call 被阻塞時，進程內核棧爲：

[<ffffffff812e31f4>] call_rwsem_down_read_failed+0x14/0x30
	[<ffffffffa0195854>] ext4_da_get_block_prep+0x1a4/0x4b0 [ext4]
	[<ffffffff811fbe17>] __block_write_begin+0x1a7/0x490
	[<ffffffffa019b71c>] ext4_da_write_begin+0x15c/0x340 [ext4]
	[<ffffffff8115685e>] generic_file_buffered_write+0x11e/0x290
	[<ffffffff811589c5>] __generic_file_aio_write+0x1d5/0x3e0
	[<ffffffff81158c2d>] generic_file_aio_write+0x5d/0xc0
	[<ffffffffa0190b75>] ext4_file_write+0xb5/0x460 [ext4]
	[<ffffffff811c64cd>] do_sync_write+0x8d/0xd0
	[<ffffffff811c6c6d>] vfs_write+0xbd/0x1e0
	[<ffffffff811c76b8>] SyS_write+0x58/0xb0
	[<ffffffff81614a29>] system_call_fastpath+0x16/0x1b
	[<ffffffffffffffff>] 0xffffffffffffffff

內核棧分析

---

write system call 阻塞位置

經過內核棧函數關鍵字找到了 OenHan 大神的博客，讀寫信號量與實時進程阻塞掛死問題 這篇文章描述的問題雖然跟我遇到的問題不一樣，但進程內核棧的分析對我頗有啓發。爲了便於分析內核函數，我 clone 了一份 linux 3.10.0 的源碼，在本地查看。

搜索源碼能夠證明，棧頂的彙編函數 ENTRY call_rwsem_down_read_failed 會調用 rwsem_down_read_failed(), 而此函數會一直阻塞在獲取 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 阻塞的位置，還要查它會什麼會阻塞在這裏。這時，棧頂的函數名 call_rwsem_down_read_failed 讓我以爲很奇怪，這不是 「write」 system call 麼，爲何會 down_read_failed？

直接搜索這個函數沒有什麼資料，但向棧底方向，再搜索其餘函數就有了線索了，原來這是在作系統磁盤塊的準備，因而就牽扯出了 ext4 的 delayed allocation 特性。

延遲分配(delayed allocation)：ext4 文件系統在應用程序調用 write system call 時並不爲緩存頁面分配對應的物理磁盤塊，當文件的緩存頁面真正要被刷新至磁盤中時，纔會爲全部未分配物理磁盤塊的頁面緩存分配儘可能連續的磁盤塊。

這一特性，能夠避免磁盤的碎片化，也能夠避免存活時間極短文件的磁盤塊分配，能很大提高系統文件 I/O 性能。

而在 write 向內存頁時，就須要查詢這些內存頁是否已經分配了磁盤塊，而後給未分配的髒頁打上延遲分配的標籤（寫入的詳細過程能夠查看 ext4 的延遲分配）。此時須要獲取此 inode 的讀鎖，若出現鎖衝突，write system call 便會 hang 住。

在掛載磁盤時使用 -o nodelalloc 選項禁用掉延遲分配特性後再進行測試，發現 write system call 被阻塞的狀況確實消失了，證實問題肯定跟延遲分配有關。

不算結論的結論

---

尋找寫鎖

知道了 write system call 阻塞在獲取讀鎖，那麼必定是內核裏有哪些地方持有了寫鎖。

ipcs 命令能夠查看系統內核此時的進程間通訊設施的狀態，它打印的項目包括消息列表(-q)、共享內存(-m)和信號量(-q)的信息，用 ipcs -q 打印內核棧的函數查看 write system call 被阻塞時的信號量，卻沒有輸出任何信息。 仔細想了一下發現其寫鎖 i_data_sem 是一把讀寫鎖，而信號量是一種 非0即1 的PV量，雖然名字裏帶有 sem，可它並非用信號量實現的。

perf lock 能夠用來分析系統內核的鎖信息，但要使用它須要從新編譯內核，添加 CONFIG_LOCKDEP、CONFIG_LOCK_STAT 選項。先不說咱們測試機的重啓須要建提案等兩天，編譯完能不能啓動得來我真的沒有信心，第一次試圖使用 perf 分析 linux 性能問題就這麼折戟了。

轉變方法

問題又卡住了，這時我也沒有太多辦法了，如今開始研究 linux 文件系統源碼是來不及了，但我還能夠問。

在 stackOverflow 上問沒人理我：how metadata journal stalls write system call?， 追着 OenHan 問了幾回也沒有什麼結論：Linux內核寫文件流程。

雖然本身無法測試 upstream linux，仍是在 kernel bugzilla 上發了個帖子：ext4 journal stalls write system call。終於有內核大佬回覆我：在 ext4_map_blocks() 函數中進行磁盤塊分配時內核會持有寫鎖。

查看了源碼裏的函數詳情，證明了這一結論：

/* * 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() 函數，長時間獲取了寫鎖呢？再追問時大佬已經很有些無奈了，linux 3.10.0 的 release 已是 5年 前了，當時確定也有一堆 bug 和缺陷，到如今已經發生了很大變更，追查這個問題可能並無很大的意義了，我只好識趣中止了。

推論

其實再向下查這個問題對我來講也沒有太大意義了，缺乏對源碼理解的積累，再看太多的資料也沒有什麼收益。就如向建築師向小孩子講建築設計，知道窗子要朝南，大門要靠近電梯這些知識並沒有意義，不瞭解建築設計的原則，只專一於一些本身能夠推導出來的理論點，根本沒辦法吸取到其中精髓。

那麼只好走到最後一步，根據查到的資料和測試現象對問題緣由作出推論，雖然沒有直接證據，但確定跟這些因素有關。

在 ext4 文件系統下，默認爲 ordered journal 模式，因此寫 metadata journal 可能會迫使髒頁刷盤， 而在 ext4 啓用 delayed allocation 特性時，髒頁可能在落盤時發現沒有分配對應的磁盤塊而分配磁盤塊。在髒頁太多的狀況下，分配磁盤塊慢時會持有 inode 的寫鎖時間過長，阻塞了 write 系統調用。

小結

---

追求知識的每一步或多或少都有其中意義，查這個問題就迫使我讀了不少外語文獻，也瞭解了一部分文件系統設計思想。

linux 真的是博大精深，但願有一天我也能對此有所貢獻。

關於本文有什麼疑問能夠在下面留言交流，若是您以爲本文對您有幫助，歡迎關注個人 微博 或 GitHub 。您也能夠在個人 博客REPO 右上角點擊 Watch 並選擇 Releases only 項來 訂閱 個人博客，有新文章發佈會第一時間通知您。