一：背景

1. 讲故事

上周四有位朋友加wx咨询他的程序出现 cpu + 线程 双高的情况，希望我能帮忙排查下，如下图：

从截图看只是线程爆高，没看到 cpu 爆高哈😂😂😂，有意思的是这位朋友说他： 一直在手动回收 ，不知道为啥看着特别想笑，但笑着笑着就哭了。

可能朋友知道老规矩，发了两份dump过来，接下来我就可以开工了，既然说高峰期分分钟上千个线程，和我前几天分享的那篇 串口 的问题很像，肯定是个别线程退不出 锁，导致 clr 需要创建更多的线程池线程来应付不断累积的 work queue，所以还是得优先看 同步块表，还是那句话，十个人用锁，八个人用 lock 🤣🤣🤣。

二： windbg 分析

1. 查找 clr 同步块表

可以用 !syncblk 看看有没有 lock 的情况。

虽然卦象上出现了超过正常指标的持有锁值：193，107，13，但直觉更告诉我，是不是死锁啦？？？ 用 sosex 扩展的 !dlk 命令可以自动检索是不是真的有？

从最后一行看没有任何 deadlocks，看样子我的直觉是错的😤😤😤。

只能回头看那最高的 193 ，表示有 1 个线程持有锁 (53号线程)，96个线程等待锁，确定了是 lock 的问题就好办了，查看它的线程栈就好啦。

2. 查看线程栈

为了稳一点，我就用 !dumpstack 调出 53 线程的托管和非托管栈，如下图：

从上面的调用栈可以看到，程序用 nlog.write 写日志后，最终卡死在 calling ntdll!ntcreatefile 这个 win32 函数上 ，我也很惊讶，是不是磁盘写入速度太低了？ 马上问了下朋友是否为 ssd ，朋友说可能不是 😂😂😂，而且朋友还说高峰期半个小时能up到 600m 日志，我想问题应该是出在磁盘写入太慢的根源上了。。。

3. 真的决定让磁盘背锅吗？

把这个答案丢给朋友好像也不太合适，让朋友换 ssd ？ 那日志量起来了ssd也扛不住怎么办？ 所以言外之意就是：耕田有责任，耕牛也得负责任，那怎么从它身上找责任呢??? 再回头看一下这个调用栈。

不知道你有没有发现，53号线程tmd的不仅要处理业务，还要调用 win32（用户态 <-> 内核态） 写入文件，这量起来了谁受的住？？？

一个高效的日志系统，走的应该是 专有线程 + 日志缓冲队列 的路子，找了下 nlog 的资料，嘿，nlog 还真提供了这种方案。

所以得优化一下 nlog 的默认配置，貌似这样就可以结束本文了，不行，既然都到这里了，我还得找点开发人员责任😁😁😁。

3. 如何找开发人员责任

如果你细心的话，会不会觉得还漏了点什么？ 对，就是那个同步块，卦象上有三条信息，对吧，为了方便查看，我再赘贴一下。

index=95 和 nloger 相关，那怎么 index=118 又和 nlog.logger 相关呢？接下来把这两个对象 0000025e2a8ded70, 00000260ea8a9b00 的源码导出来,可以用 !gcroot + !name2ee + !savemodule。

用 ilspy 打开 2.dll 后，发现了那段有趣的 logger.log() 代码，真的是太有趣了。。。如下所示。

居然在 log() 方法里加了一个锁，这是有多么不信任 nlog 哈 😂😂😂，还有一点在 writelog() 方法中使用了 task.run 记录日志，难怪朋友说分分钟上千个线程，这回我可是明白了。。。

当我以为就这样吐吐槽就结束了，不争气的我又看了另外一个 dump ，然后我就不想吐槽了😤

竟然还有 进程占用异常 。。。而且异常堆栈中不就是那个熟悉的文件创建函数 windowscreatefile 吗？？？ 好吧，好奇心驱使着我决定要拿到那个文件名，可以切换到 78 号线程，使用 !clrstack -a 调出参数和局部变量，找到最后的 filename。

还记得文章开头第二张截图吗？朋友开了webservice程序的多个副本，没想到都写一个文件了，这是大忌哈。。。

三：总结

吐槽了这么多，可能我和朋友都在做涉医行业的业务，来自于甲方的压力还是挺大的😭😭😭，最后给出的优化措施如下。

修改 nlog 的配置文件，支持 专有线程 + queue 模式，从而释放业务线程。

nlog 的写法和调用方式太杂乱，需要重新封装，对外只需提供一个接口即可，用它就要信任它。

有条件提升到 ssd。

最后的彩蛋就是反馈好消息啦😁😁😁

更多高质量干货：参见我的 github:

到此这篇关于.net医院公众号系统 线程cpu双高分析的文章就介绍到这了,更多相关.net医院公众号系统 内容请搜索以前的文章或继续浏览下面的相关文章希望大家以后多多支持！