我被 .NET8 JIT 的一個BUG反覆折磨了半年之久(JIT tier1 finally optimizations)

czd890發表於2024-10-16

很久很久沒有寫過部落格了, 正好最近園子又掙得一線生機, 必須得湊個熱鬧水一篇. 事情是這樣的, 在今年的早些時候, 把公司的一部分api伺服器的.net版本從6升級到了8, 畢竟6馬上就是EOL了(.NET6 TLS 到2024年11月12日). 沒成想在升級完的3個月後竟然觸發了一個.NET8 runtime JIT 的BUG, 而且是在程式碼沒有任何改動的情況下. 也是離奇他媽給離奇開門, 離奇到家了, 下面就給大家說說這個BUG發現和發生的過程.

我幹了什麼?

正如上面所說, 在今年的早些時候把一部分api伺服器從NET6升級到了NET8.

出現了什麼問題?

在所有升級到NET8的十幾個是API專案(基於服務scope/流量等原因切分了大約有10幾個專案, 但是公共的功能都是透過共享的lib釋出的)中, 只有其中一個專案在某些時候的其中的某一個/或少數幾個部署例項(AWS ECS Task)會一直報一個業務錯誤(出現的時間/個數等都不定). 表現的現象就是AES解密(這一部分是所有專案公共使用的)後的plaintext總是會丟失一部分字元. 而且這個例項一旦出現這個BUG, 後續所有的業務執行到這個AES解密的時候都會出現丟失字元.

初步的檢查和懷疑?

review 程式碼過後沒有發現問題, 單元測試等也都一直pass的, 所以對目前的邏輯程式碼實現的懷疑初步排除. 簡化後的程式碼如下

        public int Decrypt(byte[] buffer, string key, string iv, out byte[] decryptedData)
        {
            int decryptedByteCount = 0;
            decryptedData = new byte[buffer.Length];

            using var aes = Aes.Create();
            aes.Mode = CipherMode.CBC;
            aes.KeySize = 16;
            aes.Padding = PaddingMode.Zeros;
            
            var instPwdArray = Encoding.ASCII.GetBytes(key);
            var instSaltArray = Encoding.ASCII.GetBytes(iv);

            using (var decryptor = aes.CreateDecryptor(instPwdArray, instSaltArray))
            {
                using (var memoryStream = new MemoryStream(buffer))
                {
                    using (var cryptoStream = new CryptoStream(memoryStream, decryptor, CryptoStreamMode.Read))
                    {
                        int read;
                        do
                        {
                            read = cryptoStream.Read(decryptedData, decryptedByteCount, decryptedData.Length - decryptedByteCount);
                            decryptedByteCount += read;
                        } while (read != 0);
                    }
                }
            }
            while (decryptedData[decryptedByteCount - 1] == 0 && decryptedByteCount > 0)
            {
                decryptedByteCount--;
            }

            return decryptedByteCount;
        }

BUG具體的現象就是這個方法解密後返回明文的byte count會和預期的不一致, 即程式碼中的decryptedByteCount. 比如明文明明是10個字元, 結果返回的decryptedByteCount確是8. 呼叫方會使用這個decryptedByteCount來讀取明文.

同時線上上出現這個BUG的時候(2次)採集到的host資訊上有一個相似的特徵, 那就是CPU都是AMD EPYC 系列CPU, 而恰好在這不久前我們在另外 .NET8 服務上發生了一個.NET8 GC 在AMD EPYC CPU的異常問題, 心想著該不會又是類似的問題把, 都已經準備給dotnet/rumtime team 提ticket了, 結果ticket寫到一半, 線上又出現了這個問題, 而且採集到的host資訊裡面多了intel的CPU. 哦豁, 此路不通.

話說 AMD EPYC 的 BUG 前前後後也折騰了好幾天, 可以考慮下次在水一篇, 就不再這個JIT BUG的博文中佔用更多文字了.

行動: 增加debug程式碼進行線上除錯?

在這個核心方法的更外層呼叫的地方增加檢測程式碼, 如果檢測到觸發了這個BUG, 就執行這個方法的複製出來的另外一個方法(增加了更多的除錯資訊, 例如記錄每個引數/變數的值等), 然後, 我們就信心滿滿的將增加了除錯程式碼的版本釋出到線上, 就等著這個BUG出現, 然後抓住它! 更是和客戶保證一切盡在掌握, 在下班前就能修復這個BUG.
結果: 除錯程式碼上線後, 這個BUG就再也沒有被觸發過了. 而我就再也沒有下班了. 最後鑑於這個BUG影響範圍不大, 而且又沒有再次發生, 因此就此打住(畢竟研發資源還是很昂貴的)

2個月後的某一天, 與BUG再次不期而遇!

在即將要下班的檔口, 同事找過來和說: "我的朋友(新疆口音), 我在我這邊一個專案上呼叫了基礎類庫的AES解密, 遇到了一個丟失明文的問題, 你能幫我看看嗎?", 這個BUG在他的專案上表現比在我這邊還更離譜, 我這邊只是解密後的明文丟失最後幾個字元, 而他這邊則是丟得值剩下一個字元, 就是不管啥密文(同一個規則,長度相同)解密後都只剩下一個字元(比如 AAA 加密後是BBB, 解密 BBB後就都返回"A"了, 即期待decryptedByteCount返回3, 結果都返回了1). 而且他這邊的專案觸發這個BUG更頻繁. 上線10幾分鐘就能被觸發. 和我的同事初步瞭解後得到了一個重要的線索, 那就是頻繁執行的時候更容易觸發BUG, 於是我和我的同事說 :"我的朋友(新疆口音), 這會兒我下班了, 你先回滾到上一個版本了. 我們明天繼續"

緊跟著, 第二天深入調查, 終是找到了"它"

書接昨天, 昨天我們捕獲了一個重要的資訊, 那就是頻繁的執行就頻繁的觸發這個BUG, 於是我們在本地寫個死迴圈來呼叫這個AES解密方法, 果然不出所料, 短時間內, 執行超過大約1萬次的時候, 這個BUG總是能觸發. 而且隨著測試的進行, 越來越多的資訊被掌握. 例如: 這個BUG只在release模式下才能被觸發, 核心方法的程式碼要一行不改才能觸發. 顯然, "它" 也越來越清楚的浮出了水面, 那就是和 runtime JIT 的編譯最佳化有關係.
我們要知道dotnet的一個方法在執行多次之後, runtime會根據呼叫的時間/次數等資訊認定一個方法是不是熱點方法, 而進行一次或多次的編譯最佳化, 以提供執行效能. 而我們在本地觸發BUG前後做了dump, 從分析dump來看也證實了這個BUG確實是因為JIT二次最佳化造成的.
在BUG觸發前, dump中這個方法的版本是 00007ffe03122e70 (QuickJitted), 而BUG出現後 這個方法的版本是 Current CodeAddr: 00007ffe03134620(OptimizedTier1)

> ip2md 00007FFE0312323A
MethodDesc:   00007ffe031de8d0
Method Name:          [......].Decrypt(Byte[], System.String, System.String, Byte[] ByRef)
Class:                00007ffe031ef318
MethodTable:          00007ffe031de918
mdToken:              000000000600036B
Module:               00007ffe031dd740
IsJitted:             yes
Current CodeAddr:     00007ffe03122e70
Version History:
  ILCodeVersion:      0000000000000000
  ReJIT ID:           0
  IL Addr:            0000018f23a1c864
     CodeAddr:           00007ffe03122e70  (QuickJitted)
     NativeCodeVersion:  0000000000000000

> ip2md 00007FFE03134AE3
MethodDesc:   00007ffe031de8d0
Method Name:          [......].Decrypt(Byte[], System.String, System.String, Byte[] ByRef)
Class:                00007ffe031ef318
MethodTable:          00007ffe031de918
mdToken:              000000000600036B
Module:               00007ffe031dd740
IsJitted:             yes
Current CodeAddr:     00007ffe03134620
Version History:
  ILCodeVersion:      0000000000000000
  ReJIT ID:           0
  IL Addr:            0000018f23a1c864
     CodeAddr:           00007ffe03129cb0  (QuickJitted + Instrumented)
     NativeCodeVersion:  0000018F0054A360
     CodeAddr:           00007ffe03134620  (OptimizedTier1)
     NativeCodeVersion:  0000018F02253050
     CodeAddr:           00007ffe03122e70  (QuickJitted)
     NativeCodeVersion:  0000000000000000

調查到這裡, 我們毫不猶豫的把調查的資訊發給了dotnet/runtime team, 等待他們的深入調查. 而我們也就此打住, 為什麼打住呢? 實在是! 彙編程式碼一點都看不了! 看不了一點! 最佳化前 1千多行, 最佳化後 3千多. 在加之JIT的資料屬實不多, 無從下手.
runtime team 也非常給力, 不出一個小時他們就重現了這個BUG, 並找到了根源
在等待runtime team將這個fix向後移植到NET8的時間內, 我們也要進行修復以避免觸發這個BUG, 而修復方案也非常簡單, 只要打破這個陷入BUG的語法即可, 最終我們將程式碼改為了如下結構

 using (var aes = Aes.Create())
 {
     aes.Mode = CipherMode.CBC;
     ......
 }
 while (decryptedData[decryptedByteCount - 1] == 0 && decryptedByteCount > 0)

後話

如果我們能採集/監控足夠多的資訊,並分析在BUG發生前後的變化, 也許能更快的找到問題的根源, 例如在這個例子中, 如果我們採集/監控了了JIT的分層編譯事件,就很有可能能在更早的時間線上解決這個問題. 更可以引用AI來分析事件前後的差異,給出建議. 好期待這樣的產品.

相關連線

  • dotnet/runtime/pull/95945: Introduce BBJ_CALLFINALLYRET block kind
  • dotnet/runtime/issues/95355: Consider changing BBJ_CALLFINALLY/BBJ_ALWAYS representation of call to finally

相關文章