從應用到核心查介面超時（下）
再啟
接上文ofollow,noindex" target="_blank">從應用到核心查介面超時（中） ，查到是因為 journal 導致 write 系統呼叫被阻塞進而導致超時後，總感覺證據還不夠充分，沒有一個完美的交待。而且 leader 還想著讓我把問題排查過程分享給同事們，這讓我更加不安，擔心搞錯了方向。
在以往的部落格中，我的問題結論總是確定的，如果是推論的話，我會顯式註明。現在的情況讓我有點犯難，推論說出去擔心誤導了別人，而核心層的事，我只知道基本理論，有關此問題的結論還沒有。
於是，我只好再次踏上查這個問題的征程。
轉載隨意，請註明來源地址：https://zhenbianshu.github.io ，文章持續修訂。
列印程序核心棧
回到問題的原點，對於此問題，我能確定的資料只有穩定復現的環境和不知道什麼時候會觸發 write system call 延遲的 jar 包。
考慮到 write system call 被阻塞可長達幾百 ms，我想我能抓出當前程序的核心棧來看一下 write system call 此時被阻塞在什麼位置。
具體步驟為：
- 多個執行緒不便於抓核心棧，先將程式修改為單執行緒定量寫入。
-
使用 jar 包啟動一個程序，使用
ps拿到程序號。 -
再通過
top -H -p pid拿到佔用 cpu、記憶體等資源最多的執行緒 ID，或使用strace啟動，檢視其輸出里正在寫入的執行緒 ID。 -
使用
watch命令搭配pstack或cat /proc/pid/stack不停列印程序核心棧。具體命令為watch -n 0.1 "date +%s >> stack.log;cat /proc/pid/stack >> stack.log" - 找到 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 真的是博大精深，希望有一天我也能對此有所貢獻。