01 起因

EFC（Elastic File Client）是 NAS 自研的分布式文件系統客戶端，最近完成了對緩存架構的更新，現在支持多個客戶端之間構成分布式緩存，底層支持 NAS、CPFS 和 OSS。由于開發時間較短，一直沒有做 NAS 場景 CTO 測試的適配。

CTO：Close-to-Open，指當一個文件被關閉后，再次 open 時，文件系統必須保證之前所有通過 close 操作提交的數據已經持久化到文件系統，并且讀取時能獲取到最新的、一致的狀態。

CTO 測試的具體實現是對本地和遠端文件系統的文件執行相同的操作，在某些操作后讀取兩端文件系統的內容，比較是否相同。

• 本地為 EXT4 文件系統，符合 POSIX 語義，遠端文件系統跟本地文件系統對比，信任本地文件系統的表現。

• 讀緩存的測試是分布式的，單客戶端讀取由分布式緩存提供服務。

最近忙里偷閑適配了一下，靜靜等待測試的通過，結果沒想到發生了 data mismatch 的錯誤，因為關閉緩存直讀 NAS 的 CTO 測試在每次發版前都會跑一遍。得，緩存的鍋鐵定沒跑了，那咱就來看看這個問題。

02 錯誤類型判斷

讀數據錯誤

EFC 讀緩存在 NAS 場景下會使用 dv（data version）作為緩存的版本號，文件系統數據更新的時候會對 dv 自增。EFC 與文件系統通信的 RPC 會更新本地記錄的 dv 信息，EFC 讀緩存就會根據客戶端手上的 dv 作為版本號從緩存讀取數據。

由于這個機制的存在，所以 data mismatch 問題一眼認定為：使用了舊的 dv 讀到了緩存里的舊數據。看來問題不大，喝口水壓壓驚。

CTO 測試會對本地文件和 NAS 上的文件執行相同的操作，并在執行某些操作后檢查讀到的文件是否一致。這樣在讀到緩存舊數據的情況下，本地文件（本地 /root 下）和遠端文件系統的文件（NAS /mnt1 掛載下）內容是相同的。

由于 mnt1 還是通過 EFC 客戶端進行掛載，讀取數據還是走的緩存，依然存在讀到舊數據的可能。因此，為了排除 EFC 緩存的影響，使用 NFS 協議掛載了 NAS 文件系統后（不通過 EFC 進行掛載），通過 diff 比較本地和 NAS 上的文件內容，結果兩者竟然不一致。結果表明，文件系統數據被破壞掉了，也宣告著讀到緩存中的舊數據的想法破產。

寫數據錯誤！

調查過程陷入困局，決定看一下錯誤文件的內容有沒有新的發現。由于原始文件存在大量的不可見字符，因此使用 hexdump 將文件轉成 16 進制格式，每行顯示 16 個字符。左側為本地文件，右側為 NAS 上文件，可以看到 NAS 上文件中的字符 f (0x66) 被替換成了空字符 NULL (0x00)。

但是 CTO 測試中并不會主動寫入空字符，這些空字符是如何產生的呢？

計算錯誤字段的開始位置和結束位置：mismatch start = 0x94250 = 606800，mismatch end = 0x94ee0 + 2 = 610018，對一個 4K 頁整除可以發現錯誤段正好位于一個 page 內。

這個 CTO 數據不一致問題幾個小時的運行可以復現，每次結果的表現是一致的，均是正常字符被替換為空字符以及錯誤數據位于同一個 page 內（出現過數據錯誤開始位置正好 4K 對齊）。

這個時候開始把思路轉向為：由于緩存的引入寫壞了本地的 pagecache，當臟頁需要刷到文件系統的時候把 pagecache 里的舊數據一并刷到了文件系統，造成了文件系統數據的不一致。

明確了問題后，現在的困擾來到了是什么操作寫壞了 pagecache，以及空字符是如何產生的呢？

03 日志調查

在整個 CTO 測試期間，分析 EFC 緩存的日志，存在 6 條讀緩存日志，并且命中緩存的僅有 3 條，錯誤也就發生在這 3 次讀操作中。結合錯誤數據的 start offset (606208) 和 end offset (606208 + 3908 = 610116) 最終可以定位到第 3 次的讀操作出錯（606208 <?606800 < 610018?< 610116）。

進一步查看 CTO 測試日志，記錄了每次讀寫操作的信息。可以看到，首先通過?op_write_append?操作追加寫字符 f (0x66)，寫的數據會首先存儲在內核的 pagecache 中，然后通過?op_truncate_big?通知文件系統擴充文件長度到 610116，這樣還沒有被刷到文件系統的數據就是空字符 NULL (0x00)。接著通過op_fsync?將本地 pagecache 中的數據刷到文件系統。之后再通過?op_write_append?追加寫字符 g (0x67)。

結合緩存的引入造成 pagecache 被寫壞，分析第一個?op_write_append?的行為：

• 1.1：向內核 pagecache 中寫入數據 f，pagecache 標記為 dirty；

• 1.2：向文件系統 setattr，擴充文件長度，擴充內容用 NULL 填充，文件系統數據的版本 dv1 → dv2；

• 1.3：另一個 EFC 客戶端在緩沖不命中的情況下，從文件系統讀取了 dv2 版本的 NULL 數據，并寫到分布式緩存中；

• 1.4：在某個時刻（可能是主動 fsync 或者內核邏輯），pagecache 中的臟數據被刷到文件系統，NULL 被覆蓋為 f，文件系統數據版本 dv2 → dv3；

接著分析第二個?op_write_append?的行為：

• 2.1：由于 direct 設置為 0，是一個 buffer 寫操作，會先讀取數據到 pagecache 中。由于緩存的存在，讀取到了 dv2 版本的數據到 pagecache 中，填充為 NULL。

• 2.2：向內核 pagecache 中寫入數據 g，pagecache 標記為 dirty。

• 2.3：向文件系統 setattr，擴充文件長度，擴充內容用 NULL 填充，文件系統數據的版本 dv3 → dv4。

• 2.4：pagecache 中的臟數據被刷到文件系統，NULL 被覆蓋為 g，但是正確數據 f 被覆蓋為 pagecache 中的 NULL，造成了文件系統數據不一致。

由于 buffer 寫先讀后寫的行為，從緩存中讀取到了舊版本的 dv2 數據，但是文件系統的數據已經更新到 dv3 版本，使用最新的 dv3 讀取數據應該會緩存失效，直讀文件系統才正確（直讀文件系統讀取 dv3 數據 f 到 pagecache 中也不會存在 NULL 刷到文件系統造成數據不一致的問題）。

而 EFC 客戶端對每一個文件都會本地記錄一個 dv 號用于讀文件系統，推測 dv 發生了回退，查看 EFC 緩存日志也可以觀察到 dv 回退的現象（5676 → 5675）。

分析后認為漂移在網絡上的慢讀請求會造成 dv 回退現象發生：假設存在一個 read 請求，從文件系統讀到了 dv2，但是遲遲沒有返回。而在中途其他的 write 更新了文件系統的 dv3，并通過 RPC 更新本地版本為 dv3。之后，慢 read 帶回來 dv2 的數據到緩存中，且又使用 dv2 覆蓋了客戶端記錄的 dv3，后續用 dv2 讀取緩存就會讀到舊數據。

04 問題復原

根據上述分析，錯誤的原因總結為：緩存讀到了追加寫操作中文件系統填充為 NULL 的數據，這部分數據在下一次 buffer 寫操作中被讀取到 pagecache 中，再被新數據寫臟后刷到文件系統，緩存中的舊數據 NULL 破壞了文件系統數據，造成數據不一致。可以復原出寫壞文件系統數據的整個流程：

• client1 發起 append write，分為 write 和 setattr；

• write 寫數據 f 到 pagecache 中；

• setattr 請求會發到文件系統擴充文件長度，擴充部分填充為字符 NULL；

• client2 發起 read，讀到數據空字符 NULL 寫到緩存中；

• client1 將 pagecache 中的數據 f 刷到文件系統；

• client1 再次發起 buffer write，分為 read 和 write；

• client1 拿到舊的 dv，讀緩存讀到舊數據 NULL（buffer write 會先讀取數據到 pagecache），緩存中的數據讀到 pagecache 中；

• client1 write 了另一部分臟數據 g 到 pagecache 中（位于同一個 page）；

• client1 將 pagecache 中的數據 NULL + g 刷到文件系統，原來的數據 f 被覆蓋為 NULL，造成了文件系統數據的錯誤；

問題的根本原因在于：版本號發生回退，客戶端使用了舊版本號從緩存中讀到了舊數據。問題分析清楚后，還是比較好修復的，在本地維護了一個遞增的緩存版本號，丟棄 RPC 收到的發生回退的版本號即可。

使用修復后的版本重新運行 CTO 測試，10 輪次近 30 個小時無數據不一致發生，可以認為問題得到了修復。

05 部分 POSIX 接口底層揭秘?

到此為止，文件系統數據寫壞的問題已經分析得差不多了，但是還是對內核發到 EFC 客戶端的請求存在一知半解。紙上得來終覺淺，絕知此事要躬行。于是，寫了一個簡單的 python 程序模擬上述操作，模擬用戶對文件進行操作，觀察 EFC 客戶端收到的內核請求信息：

1.?open調用 open 打開文件；

2.?fstat調用 getattr 獲取文件大小；

3.?pwrite在文件結尾（1M）追加寫 1K 長度的字符 f。在 26s 執行時并未向 EFC 客戶端發送請求，此時將數據 f 寫到內核 pagecache 中；在 31s?ftruncate執行時調用 setattr 擴充文件系統文件長度，并調用 write 將 pagecache 中數據寫到文件系統；

4.?ftruncate擴充文件長度為 2K，和?pwrite一起僅觸發一次 setattr 調用；

5.?fsync調用 fsync 將 pagecache 中數據顯式刷到文件系統；

6.?pwrite繼續在文件末尾（1M + 1K）追加 1K 長度的字符 g。在 42s 執行時調用 read 讀取數據到內核的 pagecache 中，并將數據 g 寫到內核 pagecache 中；在 47s?close執行時調用 write 將 pagecache 中數據寫到文件系統，調用 setattr 更新文件屬性；

7.?close調用 flush 再次保證 pagecache 中數據刷到文件系統，調用 release 關閉文件；

由于內核會對用戶的操作進行很多優化，很難將內核的行為一一羅列，這里僅對本次模擬過程中內核行為和用戶操作不同的地方進行介紹：

• setattr 觸發機制

  用戶操作：pwrite（寫入 1K）與?ftruncate（擴展 2K）均涉及文件長度擴展。

  內核行為：僅在?ftruncate?時觸發一次 setattr 請求，擴展文件長度至最終值（1M + 2K）。

  差異點：pwrite?本身不會直接觸發 setattr，而是依賴后續 write 或?ftruncate?的操作。pwrite?的 1K 寫入被緩存在 pagecache 中，最終與?ftruncate?的 2K 擴展合并為一次 setattr 請求。

• buffer write 的 pagecache 延遲提交

  用戶操作：pwrite（26s）寫入 1K 數據，但未立即觸發內核請求。

  內核行為：數據先寫入 pagecache，直到?ftruncate（31s）或?fsync（36s）觸發 write 請求時才提交至文件系統。

  差異點：用戶需注意?pwrite?僅為用戶態寫入，實際落盤需依賴 write 或?fsync。

• buffer write 先讀數據到 pagecache

  用戶操作：第二次?pwrite（42s）在文件末尾追加 1K 數據。

  內核行為：內核先通過 getattr 和 read 請求讀取目標頁（4K）到 pagecache，再執行寫入。

  差異點：當寫入位置超出當前 pagecache 范圍時，內核會主動讀取缺失頁以保證寫入完整性。

• setattr 與 write 的順序問題

  用戶操作：ftruncate?擴展文件長度后，pwrite?數據需寫入新擴展區域。

  內核行為：setattr 先擴展文件長度，填充 NULL 字符；write 請求將 pagecache 數據寫入文件系統時，才真正填充空洞區域。

  差異點：若在此期間讀取文件，可能讀取到未填充的空洞數據（本文 bug 讀取到緩存的數據就發生在這次 setattr 和下一次 write 之間）

• close 的雙重作用

  用戶操作：close?僅視為關閉文件。

  內核行為：觸發 flush（47s）確保數據持久化，并調用 release（47s）釋放資源。

  差異點：close?隱含了數據刷盤操作，即使未顯式調用?fsync。

06 心得體會

這個錯誤從發現到最后解決耗時了半個多月，從開始時發現文件系統錯誤時的迷茫，到發現空字符的錯誤數據以及位于一個 page 內，提供了 pagecache 寫壞刷到文件系統的想法，之后不斷根據日志分析可能存在的寫壞文件系統操作，并驗證猜想。

整個過程還是比較坎坷的，也學到了很多新知識：比如 buffer 寫會先讀后寫，append 寫會對文件系統擴充字符先填充為空字符，以及在網絡上漂移的慢請求帶來的異常影響等。后續在分析問題以及開發過程中，有了這些先驗知識，就可以考慮得更為全面，在這里分享給大家。

附錄

import osimport timelen = 1024print_time("open")fd = os.open("/mnt1/file1M", os.O_RDWR)time.sleep(5)print_time("fstat")file_size = os.fstat(fd).st_sizeprint(file_size)time.sleep(5)data = b'f' * lenprint_time("pwrite")os.pwrite(fd, data, file_size)time.sleep(5)print_time("ftruncate")os.ftruncate(fd, file_size + 2 * len)time.sleep(5)print_time("fsync")os.fsync(fd)time.sleep(5)data = b'g' * lenprint_time("pwrite")os.pwrite(fd, data, file_size + len)time.sleep(5)print_time("close")os.close(fd)