太極限了，JDK的這個BUG都能被我踩到

捉蟲大師發表於2022-05-10
JDK

hello，大家好呀，我是小樓。

之前遇到個檔案監聽變更的問題，剛好這週末有空研究了一番，整理出來分享給大家。

從一次故障說起

我們還是從故障說起，這樣更加貼近實際，也能讓大家更快速理解背景。

有一個下發配置的服務，這個配置服務的實現有點特殊，服務端下發配置到各個服務的本地檔案，當然中間經過了一個agent，如果沒有agent也就無法寫本地檔案，然後由client端的程式監聽這個配置檔案，一旦檔案有變更，就重新載入配置，畫個架構圖大概是這樣：
image

今天的重點是檔案的變更該如何監聽（watch），我們當時的實現非常簡單：

  • 單獨起個執行緒，定時去獲取檔案的最後更新時間戳（毫秒級）
  • 記錄每個檔案的最後更新時間戳，根據這個時間戳是否變化來判斷檔案是否有變更

從上述簡單的描述，我們能看出這樣實現有一些缺點：

  • 無法實時感知檔案的變更，感知誤差在於輪詢檔案最後更新時間的間隔
  • 精確到毫秒級，如果同一毫秒內發生2次變更，且輪詢時剛好落在這2次變更的中間時，後一次變更將無法感知，但這概率很小

還好，上述兩個缺點幾乎沒有什麼大的影響。

但後來還是發生了一次比較嚴重的線上故障，這是為什麼呢？因為一個JDK的BUG，這裡直接貼出罪魁禍首：
image

BUG詳見：https://bugs.java.com/bugdatabase/view_bug.do?bug_id=8177809

在某些JDK版本下，獲取檔案的最後更新時間戳會丟失毫秒精度，總是返回整秒的時間戳，為了直觀感受，寫了個demo分別在jdk1.8.0_261和jdk_11.0.6測試（均為MacOs）：

  • jdk_1.8.0_261
    image
  • jdk_11.0.6
    image

如果是在這個BUG的影響下，只要同一秒內有2次變更，且讀取檔案最後時間戳位於這2次變更之間的時間，第2次變更就無法被程式感知了，同1秒這個概率比同一毫秒大的多的多，所以當然就被觸發了，導致了一次線上故障。

這就好比之前是滄海一粟，現在變成了大海里摸到某條魚的概率。這也能被我們碰到，真是有點極限~

WatchService—JDK內建的檔案變更監聽

當了解到之前的實現存在BUG後，我就去搜了一下Java下如何監聽檔案變更，果然被我找到了WatchService。
image

說是WatchService可以監聽一個目錄，對目錄下的檔案新增、變更、刪除進行監聽。於是我很快就寫了個demo進行測試：

public static void watchDir(String dir) {
    Path path = Paths.get(dir);
    try (WatchService watchService = FileSystems.getDefault().newWatchService()) {
        path.register(watchService, StandardWatchEventKinds.ENTRY_CREATE, StandardWatchEventKinds.ENTRY_MODIFY, StandardWatchEventKinds.ENTRY_DELETE, StandardWatchEventKinds.OVERFLOW);
        while (true) {
            WatchKey key = watchService.take();
            for (WatchEvent<?> watchEvent : key.pollEvents()) {
                if (watchEvent.kind() == StandardWatchEventKinds.ENTRY_CREATE) {
                    System.out.println("create..." + System.currentTimeMillis());
                } else if (watchEvent.kind() == StandardWatchEventKinds.ENTRY_MODIFY) {
                    System.out.println("modify..." + System.currentTimeMillis());
                } else if (watchEvent.kind() == StandardWatchEventKinds.ENTRY_DELETE) {
                    System.out.println("delete..." + System.currentTimeMillis());
                } else if (watchEvent.kind() == StandardWatchEventKinds.OVERFLOW) {
                    System.out.println("overflow..." + System.currentTimeMillis());
                }
            }
            if (!key.reset()) {
                System.out.println("reset false");
                return;
            }
        }
    } catch (Exception e) {
        e.printStackTrace();
    }
}

image

先對/tmp/file_test目錄進行監聽，然後每隔5毫秒往檔案寫資料，理論上來說，應該能收到3次事件，但實際上很奇怪，仔細看接收到modify事件的時間大概是第一次檔案修改後的9.5s左右，很奇怪，先記著，我們讀一下WatchService原始碼

>>> 1652076266609 - 1652076257097
9512

WatchService原理

WatchService watchService = FileSystems.getDefault().newWatchService()

通過debug發現，這裡的watchService實際上是PollingWatchService的例項，直接看PollingWatchService的實現：
image

PollingWatchService上來就起了個執行緒，這讓我隱隱不安。再找一下這個scheduledExecutor在哪裡用到：
image

每隔一段時間（預設為10s）去poll下，這個poll幹了什麼？程式碼太長，我截出關鍵部分：
image

果然，和我們的實現類似，也是去讀檔案的最後更新時間，根據時間的變化來發出變更事件。

換句話說，在某些JDK版本下，他也是有BUG的！
image

這也就解釋了上文提到的事件監聽為什麼是在第一個9.5s之後才發出，因為監聽註冊後，sleep了500ms後修改檔案，10s輪詢，剛好9.5s後拿到第一輪事件。

inotify—Linux核心提供的檔案監聽機制

至此，我想起了linux上的tail命令，tail 是在檔案有變更的情況下輸出檔案的末尾，理論上也是監聽了檔案變更，這塊剛好在很久之前聽過一個技術大佬分享如何自己實現tail命令，用到的底層技術就是inotify
image

簡單來說，inotify是linux核心提供的一種監控檔案變更事件的系統呼叫。如果基於此來實現，不就可以規避JDK的BUG了嗎？

但奇怪的是為什麼Java沒有用這個來實現呢？於是我又搜了搜，發現谷歌似乎有一個庫，但被刪了，看不到程式碼:
image

github上又搜到一個：https://github.com/sunmingshi/Jinotify
image

看起來是一個native的實現，需要自己編譯.so檔案，這樣就比較蛋疼了。

記得上次這麼蛋疼還是在折騰Java的unix domain socket，也是找到了一個google的庫，測試沒問題，放到線上就崩了不得不說google還是厲害，JDK提供不了的庫，我們來提供

image

於是我帶著這個疑問去問了一個搞JVM開發的朋友，結果他告訴我，Java也可以使用inotify！

image

瞬間鬥志來了，難道是我測試的姿勢不對？

我又去翻了一遍Java文件，發現在角落隱藏了這麼一段話：
image

也就是說，不同的平臺下會使用不同的實現，PollingWatchService是在系統不支援inotify的情況下使用的兜底策略。

於是將watchService的型別列印出來，在Mac上列印為：

class sun.nio.fs.PollingWatchService

在Linux上是：

class sun.nio.fs.LinuxWatchService

LinuxWatchService在Mac上是找不到這個類，我猜測應該是Mac版的JDK壓根沒把這塊程式碼打包進來。

原來我本地測試都走了兜底策略，看來是測了個寂寞。
image

於是我寫了個demo再測試一把：

public static void main(String[] args) throws Exception {
    Thread thread = new Thread(() -> watchDir("/tmp/file_test"));
    thread.setDaemon(false);
    thread.start();

    Thread.sleep(500L);

    for (int i = 0; i < 3; i++) {
        String path = "/tmp/file_test/test";
        FileWriter fileWriter = new FileWriter(path);
        fileWriter.write(i);
        fileWriter.close();
        File file = new File(path);
        System.out.println(file.lastModified());
        Thread.sleep(5);
    }
}

  • 本地Mac
    image

  • Linux
    image

可以看出，Linux上能收到的事件比本地多的多，而且接收事件的時間明顯實時多了。

為了更加準確的驗證是inotify，用strace抓一下系統呼叫，由於JVM fork出的子程式較多，所以要加-f命令，輸出太多可以存入檔案再分析：

strace -f -o s.txt java FileTime

image

果然是用到了inotify系統呼叫的，再次驗證了我們的猜想。

故障是如何修復的？

再次回到開頭的故障，我們是如何修復的呢？由於下發的檔案和讀取檔案的程式都是我們可控的，所以我們繞過了這個BUG，給每個檔案寫一個version，可以用檔案內容md5值作為version，寫入一個特殊檔案，讀取時先讀version，當version變化時再重新載入檔案。

可能你要問了，為什麼不用WatchService呢？

我也問了負責人，據說inotify在docker上執行的不是很好，經常會丟失事件，不是Java的問題，所有語言都存在這個問題，所以一直沒有使用。不過這塊找不到相關的資料，也無法證明，所以暫時擱置。

最後說幾句

有些BUG，不踩過就很難避免，程式碼只要存在BUG的可能性，就一定會暴露出來，只是時間問題。

我們要在技術上深入探究，小心求證，但產品上不必執著，可另闢蹊徑。

另外解決不了的問題時可以找這個領域的資深人士，所以平時沒事認識幾個大牛很有必要。我們今天的分析到此結束，我是小樓，下期再見~

搜尋關注微信公眾號"捉蟲大師"，後端技術分享，架構設計、效能優化、原始碼閱讀、問題排查、踩坑實踐。

相關文章