678改动日志看这里!记一次 .NET 某纺织工厂 MES系统 API 挂死分析

一、背景

1.讲故事

这个月中旬，一个朋友向我求助wx的程序线程份额很高，探讨了如何解决。屏幕截图如下：

说实话，和其他行业的程序员聊天还是很有趣的，可以交朋友，扩大自己的圈子。朋友说，因为这个bug，项目黄了。

哈哈，顾客好像不买。不能验收。有害。

既然找到我，那就让这个挂死问题彻底消失吧，上windbg说话。

二：Windbg 分析

1. 查看线程情况

既然朋友说线程高，那就从线程入手，用 !t 命令即可。

可以看到当前有 1006 个线程，其中 1000 个是 Threadpool Completion Port，这么多IO线程卡死也是第一次遇到，。

说实话，看到 Threadpool Completion Port 我就想到这是一个异步操作的回调，那为什么会有这么多IO线程被卡死 ? 要想寻找答案，抽个线程看一下。

我去，又见 FileSystemWatcher ，追这个系列的朋友应该知道，我上个月分析了一篇 记一次 .NET 某流媒体独角兽 API 句柄泄漏分析 ,这其中就是 FileSystemWatcher 导致的 文件句柄 爆高，他的形成原因是 定时刷新 appsetttings + reloadOnChange=true 所致，这世界真小，莫不会撞车了。。。 接下来我们重点关注一下它。

2. 探究 FileSystemWatcher

要想进一步分析，先用 !dso 命令看一下当前的线程栈对象。

由于线程栈上的对象是向小扩展的，所以看那个最小地址上的 Sy[] 内容就知道当前回调的是啥啦，截图如下：

经过上一役的分析经验，到这里我基本就搞清楚了，这又是一个不断构建 ConfigurationRoot 时配了 reloadOnChange: true 的经典案例，它的后果会导致内存中新增大量的 FileSystemWatcher 和 ConfigurationRoot 无法释放，而诱发点就是上图中的日志文件的不断变更导致的海量回调函数触发的卡死案例，具体详情... 请听我慢慢分解，先验证下这两个类在托管堆上的个数。

果不其然，托管堆有 3.4w 的 FileSystemWatcher 和 ConfigurationRoot，接下来就得和朋友沟通了。

3. 到底是什么代码引起的?

询问朋友为什么会有 3.4w 的 ConfigurationRoot 对象，理论上一个程序只会有一个，根据这些信息，朋友很快就找到了问题代码，截图如下：

就是因为上图中的 reloadOnChange: true 让底层构建了 FileSystemWatcher 对 a 的实时监控，从而导致内存出现了 3.4w 的对象无法释放。

三：为什么日志变更会造成程序卡死

1. 当初的困惑

其实我当初分析到这里的时候也是很困惑的，就算内存中有 3.4w 的 FileSystemWatcher，那也只是对 a 的监控，只要这个文件不变动就不会触发 3.4w 的回调，不是吗？ 可当我分析完 ConfigurationRoot 源码之后，我发现自己真tmd的天真。

2. 从源码中寻找答案

首先我们看看 FileSystemWatcher 到底监控的是啥？ 可以在它的构造函数中设一个断点，如下图所示：

很明显的看到，它 watch 的是程序根目录，这就能解释为什么日志文件有变更就会触发文件变更的回调函数，为了验证，我可以在 ReadDirectoryChangesCallback 方法中下一个断点，再丢一个日志文件到根目录，看是否能触发就知道了。。。 截图如下：

回到本案例，也就是说一旦有日志变动，就会触发 3.4w 个回调函数，如果变动100次，就会触发 340w 次回调，而日志变更不停止，自然就会因为海量的回调把程序搞死。。。对吧。。。

四：总结

本次事故可能是由于朋友偷懒，没有将 Configuration 或 IOptions 注下去，而是采用重新构建 ConfigurationRoot 的方式获取 ConnectionString，并错误的配置 reloadOnChange: true， 导致IO线程无法及时处理由于日志文件的变更导致的海量回调函数，进而导致程序挂死。

知道整个来龙去脉之后，优化措施就很简单了，提供两种方法。

1. 将 reloadOnChange: true 改成 reloadOnChange: false 。
2. 想办法将 Configuration 注入到 DataBaseConfig 类中，做成静态变量也行 。

最后上一个彩蛋，朋友太客气了。