ossfs：兩個Cache引發的Bug

ossfs是一個可以将oss的bucket挂載到本地檔案系統的工具，使用者可以像操作本地檔案一樣（ls/cat/stat）操作oss的object。

在跑ossfs的測試時，一個case偶爾會fail，确認原因時，發現這個case的邏輯非常簡單：

case分為3步：

寫一點東西到檔案<code>test-file</code>

通過bash中的重定向指令<code>: &gt; test-file</code>将檔案變成空

檢查檔案的size是0

失敗發生在第3步，有時檔案的size不是0！how can?

于是決定用簡單的方法重制：

挂載ossfs到<code>/tmp/ossfs</code>

用一個腳本反複地跑，直到fail

果然很容易就重制了。

開啟ossfs的debug模式：

注意上面的<code>stdbuf -ol -el</code>可以讓程式的輸出是line buffered，避免有些log沒有及時打出來的情況。（ 這個很關鍵 ）<code>-f -d -d -s</code>讓ossfs輸出debug日志。

再運作重制腳本，出現fail時，ossfs的輸出是：

其中xattr相關的日志可以忽略。上面的log中看到：

第5325次操作是open(o_trunc)，對應的是<code>: &gt; $file</code>這句

之後的flush和release是關閉檔案後的操作

第5330次的getattr操作對應的是判斷檔案size為0: <code>[ ! -s $file ]</code>

注意到<code>getattr</code>下面并沒有發送http head請求向oss擷取檔案的資訊，從代碼中可以看到，ossfs中有一個statcache，使用者緩存檔案的stat資訊，這樣能夠避免頻繁地發送head請求以擷取檔案的size等meta資訊。

是以這次<code>getattr</code>是直接從ossfs的stat cache中取的。在代碼中加入更多的debug資訊後看到，這次<code>getattr</code>拿到的size是12，就是上次操作的size。為什麼cache沒有被更新呢？

從代碼中看到在<code>s3fs_release</code>中進行了<code>delstat</code>的操作：

同時，還有一段頗長的注釋。可以看到是由于fuse的一個known issue，導緻<code>s3fs_release</code>函數是被異步調用的，也就是說發生了現在的時序：

由于cache沒有及時被删掉，導緻第3步的操作擷取到的stat還是第1步的操作放到cache中的結果。

既然在<code>release</code>中<code>delstat</code>太晚了，那麼将它提前到<code>flush</code>中總可以了吧？于是做了下面的fix：

修複後再跑，發現還是會随機fail。

這次fail時的log更加奇怪：

注意到最後一步并不是<code>getattr</code>。為什麼<code>[ ! -s $file ]</code>這句話沒有對應的getattr呢？手動執行<code>stat -c %s /tmp/ossfs/test-cache</code>，發現第執行一次都會增加一條log：

連續兩次執行的結果如上，可以看到第1次執行的時候由于cache裡沒有，發生一次head請求，第二次的時候直接從cache裡讀出來。

循環執行100遍：<code>for i in $(seq 100); do stat -c %s /tmp/ossfs; done</code>，

發現并沒有增加100條log！而隻增加了1條！

為什麼手動執行每次都能觸發，但是循環就不行？猜測原因可能是：

fuse會對請求作group，短時間内的100次請求被group處理了

檔案系統會對檔案的stat進行cache

針對第1條猜測，去看libfuse的代碼，并沒有發現有group處理的邏輯。

針對第2條猜測，請教了核心和存儲相關的同學，得到的答案是即使有cache（page cache)也不應該這麼快就過期。

于是再去看fuse的代碼，一個偶然的機會，看到fuse居然有一個attr_timeout，預設的時間是1s！上面的問題終于有了答案：fuse對attr有cache。

本以為到此為止，問題都解決了。但是fuse的這個解釋說隻要檔案操作是經過核心的，<code>attr_timeout</code>不為0時正确性是保證的：對這個檔案進行了相關的操作時，核心會invalidate這個cache（使cache失效）。

那麼為什麼truncate檔案這個操作沒有invalidate這個cache呢？突然想到有沒有可能還是release的問題，要到release時才會invalidate這個cache，而release可能被異步執行。皓然認為不應該：為什麼要到release才會去更新？

而我用c語言做了一個實驗：用o_trunc的方式打開一個有内容的檔案，然後就sleep，并不關閉它。另外一邊用stat去看這個檔案的大小，結果是open後檔案的size就變成0了。

是以應該不是release的問題。

為了查清這個cache到底什麼時候被失效，決定去看一看kernel的代碼。我出問題的系統是centos6.5，核心是2.6.32版本的，于是去這裡下載下傳了2.6.32的代碼，看到fs/fuse/file.c中：

從這裡看到，如果以o_trunc的方式open的話，是立即就會失效cache的。那為什麼問題還會出現呢？我隻能懷疑上面的<code>if (fc-&gt;atomic_o_trunc &amp;&amp; (file-&gt;f_flags &amp; o_trunc)) {</code>中有某個條件不滿足：

<code>fc-&gt;atomic_o_trunc</code>，翻libfuse的代碼，看到這個值預設是<code>true</code>的，而

通過<code>-oatomic_o_trunc</code>參數挂載，問題也依然存在

<code>file-&gt;f_flags</code>中沒有包含o_trunc，通過log可以看到open的flags是

<code>0x8201</code>，而o_trunc是<code>0x0200</code>

上面的兩個條件都是滿足的，為什麼<code>fuse_invalidate_attr</code>沒有生效呢？為了搞清楚這個問題，我決定在fuse的代碼中列印一些調試資訊，然後重新編譯一個fuse子產品。

得益于當初搞cubieboard時編譯無線網卡驅動，編譯核心子產品應該也不難。好在centos的wiki還是很詳細，參考下來很容易就能編譯好。

當我下載下傳完centos-6.5的核心源碼正準備對fuse子產品稍加修改時，一個尴尬的事情發生了：<code>fs/fuse/file.c</code>中并沒有<code>fuse_invalidate_attr</code>這一段：

原來如此！ 而我手動添加這幾行代碼後再編譯&amp;替換掉fuse子產品，一切正常！

進一步blame發現，這個patch是在2010年的時候進的，是在2.6.32之後進的，而centos-6.5的核心并沒有包含這個patch。

在測試中還發現一個現象，使用<code>stat -c %s $file</code>和<code>[ ! -s $file ]</code>這兩個方式判斷檔案的size為0，重制的機率不一樣。後者重制的機率要高一些。通過<code>strace</code>發現這兩個方法幾乎沒有差別，一個調用<code>stat</code>，一個調用<code>lstat</code>。

後來想明白了，原因是前者比後者慢，使用後者時有更大的機率release還沒有調用完。而release中包含了<code>fuse_invalidate_attr</code>的邏輯。

<code>stat -c %s $file</code>需要建立一個程序（來運作<code>stat</code>），而<code>[ ! -s $file ]</code>是在和<code>bash</code>同樣的程序中進行的，是以會更快。