个人中心
gpt4 book ai didi

.NET医院公众号系统线程CPU双高问题分析

转载 作者：qq735679552 更新时间：2022-09-27 22:32:09 26 4
gpt4 key购买 nike

CFSDN坚持开源创造价值，我们致力于搭建一个资源共享平台，让每一个IT人在这里找到属于你的精彩世界.

这篇CFSDN的博客文章.NET医院公众号系统线程CPU双高问题分析由作者收集整理，如果你对这篇文章有兴趣，记得点赞哟.

一：背景

1. 讲故事

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

.NET医院公众号系统线程CPU双高问题分析

.NET医院公众号系统线程CPU双高问题分析

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

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

二： windbg 分析

1. 查找 clr 同步块表

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

  1. 0:000> !syncblk 
  2. Index SyncBlock MonitorHeld Recursion Owning Thread Info  SyncBlock Owner 
  3.    95 00000262b8a30ca8          193         1 00000262b8a36b50 116b8  53   0000025e2a8ded70 System.Object 
  4.   118 00000262b8a32098          107         1 00000262bad503b0 710c 135   00000260ea8a9b00 NLog.Logger 
  5.   200 00000262ba236cc8           13         1 00000262b9df1660 8858  69   0000025e2a8dcdf0 System.Object 
  6. ----------------------------- 
  7. Total           305 
  8. CCW             3 
  9. RCW             6 
  10. ComClassFactory 0 
  11. Free            116 

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

  1. 0:000> !dlk 
  2. Examining SyncBlocks... 
  3. Scanning for ReaderWriterLock instances... 
  4. Scanning for holders of ReaderWriterLock locks... 
  5. Scanning for ReaderWriterLockSlim instances... 
  6. Scanning for holders of ReaderWriterLockSlim locks... 
  7. Examining CriticalSections... 
  8. Scanning for threads waiting on SyncBlocks... 
  9. Scanning for threads waiting on ReaderWriterLock locks... 
  10. Scanning for threads waiting on ReaderWriterLocksSlim locks... 
  11. Scanning for threads waiting on CriticalSections... 
  12. No deadlocks detected. 

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

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

2. 查看线程栈

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

.NET医院公众号系统线程CPU双高问题分析

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

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

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

  1. 0:053> !clrstack 
  2. OS Thread Id: 0x116b8 (53) 
  3.         Child SP               IP Call Site 
  4. 0000006d65d3d238 00007ff849ac65b4 [InlinedCallFrame: 0000006d65d3d238] NLog.Internal.Win32FileNativeMethods.CreateFile(System.String, FileAccess, Int32, IntPtr, CreationDisposition, NLog.Targets.Win32FileAttributes, IntPtr) 
  5. 0000006d65d3d238 00007ff7d2d8c33e [InlinedCallFrame: 0000006d65d3d238] NLog.Internal.Win32FileNativeMethods.CreateFile(System.String, FileAccess, Int32, IntPtr, CreationDisposition, NLog.Targets.Win32FileAttributes, IntPtr) 
  6. 0000006d65d3d1f0 00007ff7d2d8c33e DomainBoundILStubClass.IL_STUB_PInvoke(System.String, FileAccess, Int32, IntPtr, CreationDisposition, NLog.Targets.Win32FileAttributes, IntPtr) 
  7. 0000006d65d3d300 00007ff7d2d8bcdc NLog.Internal.FileAppenders.BaseFileAppender.WindowsCreateFile(System.String, Boolean) 
  8. 0000006d65d3d380 00007ff7d2d8b94f NLog.Internal.FileAppenders.BaseFileAppender.TryCreateFileStream(Boolean) 
  9. 0000006d65d3d3e0 00007ff7d2d8b673 NLog.Internal.FileAppenders.BaseFileAppender.CreateFileStream(Boolean) 
  10. 0000006d65d3d440 00007ff7d2d8b501 NLog.Internal.FileAppenders.RetryingMultiProcessFileAppender.Write(Byte[]) 
  11. 0000006d65d3d490 00007ff7d2d8aca0 NLog.Targets.FileTarget.WriteToFile(System.String, NLog.LogEventInfo, Byte[], Boolean) 
  12. 0000006d65d3d4e0 00007ff7d2a44dd3 NLog.Targets.FileTarget.ProcessLogEvent(NLog.LogEventInfo, System.String, Byte[]) 
  13. 0000006d65d3d550 00007ff7d2a485c9 NLog.Targets.Target.Write(NLog.Common.AsyncLogEventInfo) 
  14. 0000006d65d3d590 00007ff7d2a487b7 NLog.Targets.Target.WriteAsyncLogEvent(NLog.Common.AsyncLogEventInfo) 
  15. 0000006d65d3d610 00007ff7d2a48ab5 NLog.LoggerImpl.WriteToTargetWithFilterChain(NLog.Internal.TargetWithFilterChain, NLog.LogEventInfo, NLog.Common.AsyncContinuation) 
  16. 0000006d65d3d670 00007ff7d2a38c45 NLog.LoggerImpl.Write(System.Type, NLog.Internal.TargetWithFilterChain, NLog.LogEventInfo, NLog.LogFactory) 
  17. 0000006d65d3d6d0 00007ff7d2a39282 NLog.Logger.Trace(System.String) 

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

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

.NET医院公众号系统线程CPU双高问题分析

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

3. 如何找开发人员责任

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

  1. 0:000> !syncblk 
  2. Index SyncBlock MonitorHeld Recursion Owning Thread Info  SyncBlock Owner 
  3.    95 00000262b8a30ca8          193         1 00000262b8a36b50 116b8  53   0000025e2a8ded70 System.Object 
  4.   118 00000262b8a32098          107         1 00000262bad503b0 710c 135   00000260ea8a9b00 NLog.Logger 
  5.   200 00000262ba236cc8           13         1 00000262b9df1660 8858  69   0000025e2a8dcdf0 System.Object 

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

  1. 0:053> !gcroot 0000025e2a8ded70 
  2. Thread 116b8: 
  3.     0000006d65d3d590 00007ff7d2a487b7 NLog.Targets.Target.WriteAsyncLogEvent(NLog.Common.AsyncLogEventInfo) 
  4.         rbp-48: 0000006d65d3d5b8 
  5.             ->  0000025e2a8ded70 System.Object 
  6. 0:053> !name2ee *!NLog.Targets.Target.WriteAsyncLogEvent 
  7. -------------------------------------- 
  8. Module:      00007ff7d2b172d8 
  9. Assembly:    NLog.dll 
  10. Token:       0000000006000b5e 
  11. MethodDesc:  00007ff7d2be3330 
  12. Name:        NLog.Targets.Target.WriteAsyncLogEvent(NLog.Common.AsyncLogEventInfo) 
  13. JITTED Code Address: 00007ff7d2a48700 
  14. -------------------------------------- 
  15. 0:053> !savemodule 00007ff7d2b172d8 E:\dumps\1.dll 
  16. 3 sections in file 
  17. section 0 - VA=2000, VASize=7faa4, FileAddr=200, FileSize=7fc00 
  18. section 1 - VA=82000, VASize=3e8, FileAddr=7fe00, FileSize=400 
  19. section 2 - VA=84000, VASize=c, FileAddr=80200, FileSize=200 
  20.  
  21. 0:053> !gcroot 00000260ea8a9b00 
  22. Thread 710c: 
  23.     0000006d68f3df30 00007ff7d2d8a3b2 xxx.Logger.log(System.String) 
  24.         rdi:  
  25.             ->  00000260ea8a9b00 NLog.Logger 
  26. 0:053> !name2ee *!xxx.Logger.log 
  27. -------------------------------------- 
  28. Module:      00007ff7d29b5558 
  29. Assembly:    xxx.dll 
  30. Token:       0000000006001ead 
  31. MethodDesc:  00007ff7d29b9a38 
  32. Name:        xxx.Logger.log(System.String) 
  33. JITTED Code Address: 00007ff7d2d8a260 
  34. -------------------------------------- 
  35. 0:053> !savemodule 00007ff7d29b5558 E:\dumps\2.dll 
  36. 3 sections in file 
  37. section 0 - VA=2000, VASize=221cf0, FileAddr=200, FileSize=221e00 
  38. section 1 - VA=224000, VASize=3c8, FileAddr=222000, FileSize=400 
  39. section 2 - VA=226000, VASize=c, FileAddr=222400, FileSize=200 

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

  1. public class Logger 
  2. { 
  3.     private static Logger Log = LogManager.GetLogger(""); 
  4.  
  5.     private static object lockCache = new object(); 
  6.  
  7.     public static void WriteLog(string message) 
  8.     { 
  9.         Task.Run(delegate 
  10.         { 
  11.             log(message); 
  12.         }); 
  13.     } 
  14.  
  15.     public static void log(string message) 
  16.     { 
  17.         try 
  18.         { 
  19.             if (message.Contains("xxxxxxx")) 
  20.             { 
  21.                 lock (Log) 
  22.                 { 
  23.                     Log.Warn("    " + message + "\r\n\r\n"); 
  24.                 } 
  25.             } 
  26.             else 
  27.             { 
  28.                 lock (Log) 
  29.                 { 
  30.                     Log.Info("    " + message + "\r\n\r\n"); 
  31.                 } 
  32.             } 
  33.         } 
  34.         catch (Exception) 
  35.         { 
  36.         } 
  37.     } 
  38.  
  39.     public static void WriteLog(string message, params object[] args) 
  40.     { 
  41.         lock (Log) 
  42.         { 
  43.             Log.Info("    " + string.Format(message, args)); 
  44.         } 
  45.     } 
  46. } 

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

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

  1. 0:000> !t 
  2. ThreadCount:      200 
  3. UnstartedThread:  0 
  4. BackgroundThread: 200 
  5. PendingThread:    0 
  6. DeadThread:       0 
  7. Hosted Runtime:   no 
  8.                                                                                                         Lock   
  9.        ID OSID ThreadOBJ           State GC Mode     GC Alloc Context                  Domain           Count Apt Exception 
  10.   78   47 afb8 000001cd7abbf1d0  3029220 Preemptive  000001CBB81648C0:000001CBB8166318 000001cd798a9d30 2     MTA (Threadpool Worker) System.IO.FileLoadException 000001cbb81644a8 
  11.  
  12. 0:000> !PrintException /d 000001cbb81644a8 
  13. Exception object: 000001cbb81644a8 
  14. Exception type:   System.IO.FileLoadException 
  15. Message:          另一个程序正在使用此文件，进程无法访问。 (异常来自 HRESULT:0x80070020) 
  16. InnerException:   <none> 
  17. StackTrace (generated): 
  18.     SP               IP               Function 
  19.     0000001B3703E750 0000000000000000 mscorlib_ni!System.Runtime.InteropServices.Marshal.ThrowExceptionForHRInternal(Int32, IntPtr)+0x1 
  20.     0000001B3703E750 00007FF7D2D30D87 UNKNOWN!NLog.Internal.FileAppenders.BaseFileAppender.WindowsCreateFile(System.String, Boolean)+0x157 
  21.     0000001B3703E7D0 00007FF7D2D3092F UNKNOWN!NLog.Internal.FileAppenders.BaseFileAppender.TryCreateFileStream(Boolean)+0x5f 
  22.     0000001B3703E830 00007FF7D2D30593 UNKNOWN!NLog.Internal.FileAppenders.BaseFileAppender.CreateFileStream(Boolean)+0xd3 
  23.  
  24. StackTraceString: <none> 
  25. HResult: 80070020 
  26. The current thread is unmanaged  

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

  1. 0:078> !clrstack -a 
  2. OS Thread Id: 0xafb8 (78) 
  3. 0000001b3703e750 00007ff7d2d30ce1 NLog.Internal.FileAppenders.BaseFileAppender.WindowsCreateFile(System.String, Boolean) 
  4.     PARAMETERS: 
  5.         this (<CLR reg>) = 0x000001c9771abf40 
  6. 0:078> !do 0x000001c9771abf40 
  7. Name:        NLog.Internal.FileAppenders.RetryingMultiProcessFileAppender 
  8. Fields: 
  9.               MT    Field   Offset                 Type VT     Attr            Value Name 
  10. 00007ff830f88760  40000dd        8        System.Random  0 instance 000001c9771abf80 random 
  11. 00007ff830f99808  40000de       10        System.String  0 instance 000001c9772fd418 <FileName>k__BackingField 
  12.  
  13. 0:078> !DumpObj /d 000001c9772fd418 
  14. Name:        System.String 
  15. MethodTable: 00007ff830f99808 
  16. EEClass:     00007ff830876cb8 
  17. Size:        142(0x8e) bytes 
  18. File:        C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll 
  19. String:      D:\xxx\wwwroot\WebService\log\2021-04-16\file.txt 

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

三：总结

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

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

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

有条件提升到 ssd.

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

.NET医院公众号系统线程CPU双高问题分析

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

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

原文链接：https://www.cnblogs.com/huangxincheng/p/14699101.html 。

最后此篇关于.NET医院公众号系统线程CPU双高问题分析的文章就讲到这里了,如果你想了解更多关于.NET医院公众号系统线程CPU双高问题分析的内容请搜索CFSDN的文章或继续浏览相关文章，希望大家以后支持我的博客！ 。

26 4 0
文章推荐： php+pdo实现的购物车类完整示例
文章推荐： 用scikit-learn和pandas学习线性回归的方法
文章推荐： 正版phpstorm免费激活步骤教程详解
文章推荐： 在pyqt5中QLineEdit里面的内容回车发送的实例
qq735679552
个人简介

我是一名优秀的程序员,十分优秀！

滴滴打车优惠券免费领取
滴滴打车优惠券
Copyright 2021 - 2024 cfsdn All Rights Reserved 蜀ICP备2022000587号
广告合作:1813099741@qq.com 6ren.com