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

这篇文章介绍了我被 .NET8 JIT 的一个BUG反复折磨了半年之久(JIT tier1 finally optimizations)，分享给大家做个参考，收藏极客之家收获更多编程知识

很久很久没有写过博客了, 正好最近园子又挣得一线生机, 必须得凑个热闹水一篇. 事情是这样的, 在今年的早些时候, 把公司的一部分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来分析事件前后的差异,给出建议. 好期待这样的产品.

版权声明：本文来自互联网用户投稿，该文观点仅代表作者本人，不代表本站立场。本站仅提供信息存储空间服务，不拥有所有权，不承担相关法律责任。如若内容造成侵权/违法违规/事实不符，请联系邮箱：jacktools123@163.com进行投诉反馈，一经查实，立即删除！