從應用到核心查介面超時(下)
再啟
接上文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 真的是博大精深,希望有一天我也能對此有所貢獻。