记一次 .NET医院公众号程序 线程CPU双高分析

一:背景

1. 讲故事

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

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

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

二:windbg 分析

1. 查找 CLR 同步块表

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


0:000> !syncblk
Index SyncBlock MonitorHeld Recursion Owning Thread Info  SyncBlock Owner95 00000262b8a30ca8          193         1 00000262b8a36b50 116b8  53   0000025e2a8ded70 System.Object118 00000262b8a32098          107         1 00000262bad503b0 710c 135   00000260ea8a9b00 NLog.Logger200 00000262ba236cc8           13         1 00000262b9df1660 8858  69   0000025e2a8dcdf0 System.Object
-----------------------------
Total           305
CCW             3
RCW             6
ComClassFactory 0
Free            116

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


0:000> !dlk
Examining SyncBlocks...
Scanning for ReaderWriterLock instances...
Scanning for holders of ReaderWriterLock locks...
Scanning for ReaderWriterLockSlim instances...
Scanning for holders of ReaderWriterLockSlim locks...
Examining CriticalSections...
Scanning for threads waiting on SyncBlocks...
Scanning for threads waiting on ReaderWriterLock locks...
Scanning for threads waiting on ReaderWriterLocksSlim locks...
Scanning for threads waiting on CriticalSections...
No deadlocks detected.

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

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

2. 查看线程栈

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

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

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

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


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

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

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

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

3. 如何找开发人员责任

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


0:000> !syncblk
Index SyncBlock MonitorHeld Recursion Owning Thread Info  SyncBlock Owner95 00000262b8a30ca8          193         1 00000262b8a36b50 116b8  53   0000025e2a8ded70 System.Object118 00000262b8a32098          107         1 00000262bad503b0 710c 135   00000260ea8a9b00 NLog.Logger200 00000262ba236cc8           13         1 00000262b9df1660 8858  69   0000025e2a8dcdf0 System.Object

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


0:053> !gcroot 0000025e2a8ded70
Thread 116b8:0000006d65d3d590 00007ff7d2a487b7 NLog.Targets.Target.WriteAsyncLogEvent(NLog.Common.AsyncLogEventInfo)rbp-48: 0000006d65d3d5b8->  0000025e2a8ded70 System.Object
0:053> !name2ee *!NLog.Targets.Target.WriteAsyncLogEvent
--------------------------------------
Module:      00007ff7d2b172d8
Assembly:    NLog.dll
Token:       0000000006000b5e
MethodDesc:  00007ff7d2be3330
Name:        NLog.Targets.Target.WriteAsyncLogEvent(NLog.Common.AsyncLogEventInfo)
JITTED Code Address: 00007ff7d2a48700
--------------------------------------
0:053> !savemodule 00007ff7d2b172d8 E:\dumps\1.dll
3 ps in file
p 0 - VA=2000, VASize=7faa4, FileAddr=200, FileSize=7fc00
p 1 - VA=82000, VASize=3e8, FileAddr=7fe00, FileSize=400
p 2 - VA=84000, VASize=c, FileAddr=80200, FileSize=2000:053> !gcroot 00000260ea8a9b00
Thread 710c:0000006d68f3df30 00007ff7d2d8a3b2 xxx.Logger.log(System.String)rdi: ->  00000260ea8a9b00 NLog.Logger
0:053> !name2ee *!xxx.Logger.log
--------------------------------------
Module:      00007ff7d29b5558
Assembly:    xxx.dll
Token:       0000000006001ead
MethodDesc:  00007ff7d29b9a38
Name:        xxx.Logger.log(System.String)
JITTED Code Address: 00007ff7d2d8a260
--------------------------------------
0:053> !savemodule 00007ff7d29b5558 E:\dumps\2.dll
3 ps in file
p 0 - VA=2000, VASize=221cf0, FileAddr=200, FileSize=221e00
p 1 - VA=224000, VASize=3c8, FileAddr=222000, FileSize=400
p 2 - VA=226000, VASize=c, FileAddr=222400, FileSize=200

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


public class Logger
{private static Logger Log = LogManager.GetLogger("");private static object lockCache = new object();public static void WriteLog(string message){Task.Run(delegate{log(message);});}public static void log(string message){try{if (message.Contains("xxxxxxx")){lock (Log){Log.Warn("    " + message + "\r\n\r\n");}}else{lock (Log){Log.Info("    " + message + "\r\n\r\n");}}}catch (Exception){}}public static void WriteLog(string message, params object[] args){lock (Log){Log.Info("    " + string.Format(message, args));}}
}

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

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


0:000> !t
ThreadCount:      200
UnstartedThread:  0
BackgroundThread: 200
PendingThread:    0
DeadThread:       0
Hosted Runtime:   noLock  ID OSID ThreadOBJ           State GC Mode     GC Alloc Context                  Domain           Count Apt Exception78   47 afb8 000001cd7abbf1d0  3029220 Preemptive  000001CBB81648C0:000001CBB8166318 000001cd798a9d30 2     MTA (Threadpool Worker) System.IO.FileLoadException 000001cbb81644a80:000> !PrintException /d 000001cbb81644a8
Exception object: 000001cbb81644a8
Exception type:   System.IO.FileLoadException
Message:          另一个程序正在使用此文件,进程无法访问。 (异常来自 HRESULT:0x80070020)
InnerException:   <none>
StackTrace (generated):SP               IP               Function0000001B3703E750 0000000000000000 mscorlib_ni!System.Runtime.InteropServices.Marshal.ThrowExceptionForHRInternal(Int32, IntPtr)+0x10000001B3703E750 00007FF7D2D30D87 UNKNOWN!NLog.Internal.FileAppenders.BaseFileAppender.WindowsCreateFile(System.String, Boolean)+0x1570000001B3703E7D0 00007FF7D2D3092F UNKNOWN!NLog.Internal.FileAppenders.BaseFileAppender.TryCreateFileStream(Boolean)+0x5f0000001B3703E830 00007FF7D2D30593 UNKNOWN!NLog.Internal.FileAppenders.BaseFileAppender.CreateFileStream(Boolean)+0xd3StackTraceString: <none>
HResult: 80070020
The current thread is unmanaged 

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

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

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

三:总结

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

  • 修改 NLog 的配置文件,支持 专有线程 + Queue 模式,从而释放业务线程。

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

  • 有条件提升到 SSD。

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

END

工作中的你,是否已遇到 ... 

1. CPU爆高

2. 内存暴涨

3. 资源泄漏

4. 崩溃死锁

5. 程序呆滞

等紧急事件,全公司都指望着你能解决...  危难时刻才能展现你的技术价值,作为专注于.NET高级调试的技术博主,欢迎微信搜索: 一线码农聊技术,免费协助你分析Dump文件,希望我能将你的踩坑经验分享给更多的人。

本文来自互联网用户投稿,该文观点仅代表作者本人,不代表本站立场。本站仅提供信息存储空间服务,不拥有所有权,不承担相关法律责任。如若转载,请注明出处:http://www.mzph.cn/news/302952.shtml

如若内容造成侵权/违法违规/事实不符,请联系多彩编程网进行投诉反馈email:809451989@qq.com,一经查实,立即删除!

相关文章

各种学习资料收录

http://topic.csdn.net/u/20120111/18/2DACB0AB-1C29-4AB7-9EF9-F53D5B0A8CD6.html C#串口操作资料转载于:https://www.cnblogs.com/youshan/archive/2012/01/19/2327324.html

谷歌搜索,揭示人性最黑暗的5个秘密

《卫报》网站发布文章指出&#xff0c;我们能够从我们在网上问的问题获得对自己更多的了解呢。美国数据科学家塞斯斯蒂芬斯-大卫多维茨&#xff08;Seth Stephens-Davidowitz&#xff09;通过分析谷歌的匿名搜索数据&#xff0c;揭示了我们最黑暗的一些秘密&#xff0c;揭露了我…

通过Dapr实现一个简单的基于.net的微服务电商系统(七)——一步一步教你如何撸Dapr之服务限流...

在一般的互联网应用中限流是一个比较常见的场景&#xff0c;也有很多常见的方式可以实现对应用的限流比如通过令牌桶通过滑动窗口等等方式都可以实现&#xff0c;也可以在整个请求流程中进行限流比如客户端限流就是在客户端通过随机数直接返回成功失败来决定是否发起请求。也可…

(转)完美画质 3D游戏反锯齿技术浅析 .

完美的画面已经离我们不再遥远——反锯齿技术浅析 不管现今的游戏画面有多完美&#xff0c;人物和环境有多真实&#xff0c;但游戏画面的构成的主要方式仍然没有得到改善&#xff1a;一帧画面由成千上万像素构成。这意味着物体多边形的轮廓最终是锯齿状的图形。所以画面质量不可…

业余时间学数据分析,如何快速上手

广泛被应用的数据分析谷歌的数据分析可以预测一个地区即将爆发的流感&#xff0c;从而进行针对性的预防&#xff1b;淘宝可以根据你浏览和消费的数据进行分析&#xff0c;为你精准推荐商品&#xff1b;口碑极好的网易云音乐&#xff0c;通过其相似性算法&#xff0c;为不同的人…

java连接mysql数据库连接池_java使用原生MySQL实现数据的增删改查以及数据库连接池技术...

一、工具类及配置文件准备工作1.1 引入jar包使用原生MySQL&#xff0c;只需要用到MySQL连接的jar包&#xff0c;maven引用方式如下&#xff1a;mysqlmysql-connector-java5.1.481.2 jdbc.properties文件配置在resources文件夹根目录&#xff0c;新增jdbc.properties配置文件&am…

64位Visual Studio 2022,微软在下一盘大棋!

有没有跟我一样奇怪过&#xff0c;都2021年了&#xff0c;用的还是VS2019&#xff1f;原来微软是憋大招去了&#xff0c;4月18号Amanda的一篇博文宣布了一则重磅消息——Visual Studio 2022 首个预览版将于今年夏季发布 &#xff0c;并且终于成为万众期待的 64 位版&#xff01…

如何添加自定义icon

(1)一般命令行程序编译后是一个方框图标。 我们可以自定义&#xff1a; Project -> Add to project -> New... 选择Resource Script&#xff0c;新建一个资源脚本&#xff0c;这样左面就多了一个资源视图 然后Project -> Add to project -> File&#xff0c;加进…

mysql 5.7.17 源码安装_mysql5.7.17源码安装

创建用户和目录groupadd mysqluseradd -r -g mysql mysqlmkdir -p /data/mysql/standby/datamkdir -p /data/mysql/standby/tmpmkdir -p /data/mysql/standby/elogmkdir -p /data/mysql/standby/blogchown -R mysql:root /data/mysql配置yum源cd /etc/yum.repos.d/rm -rf *vi c…

跟几个程序员聊了聊他们的每月薪资收入

阅读本文大概需要6分钟。我一直有一个技术小群&#xff0c;这个群最初是在360当新人入职导师带的几个人&#xff0c;和大家挺聊得来就建了一个群&#xff0c;没想到居然存在了6年之久。压力大的时候就在群里和大家相互调侃或者拉拉家常&#xff0c;偶尔谁跳槽了也会喷喷前东家&…

开通博客

今天注册了博客园并且开通了博客&#xff01; 我想用博客来记录并分享我学习编程过程和知识。 希望大家予以支持和帮助。转载于:https://www.cnblogs.com/crislina/archive/2012/01/28/2330629.html

【重磅】MIT发布2018年“全球十大突破性技术”

“有些技术已经应用多年&#xff0c;有些则是意外之喜。无论如何&#xff0c;以下是我们认为将在未来的几年对我们的工作和生活产生巨大影响的技术突破。”北京时间2018年2月21日&#xff0c;《麻省理工科技评论》揭晓了2018年“全球十大突破性技术”&#xff0c;这份全球新兴科…

mysql必须的组件_mysql innodb的重要组件

innodb包涵如下几个组件一、innodb_buffer_pool&#xff1a;1  它主要用来缓存数据与索引(准确的讲由于innodb中的表是由聚集索引组织的&#xff0c;所以数据只不是过主键这个索引的叶子结点)。二、change buffer:1  如果更新语句要更新二级索引的记录&#xff0c;但是记录…

[Stardust]星尘配置中心

在分布式系统开发中&#xff0c;配置中心必不可少。在中通几年时间里&#xff0c;为了配合大数据计算平台&#xff0c;统一管理数百个微小应用&#xff0c;设计了一套轻量级配置中心。星尘配置中心在其理念基础上改进&#xff0c;针对中小团队而全新设计&#xff01;源码&#…

oracle中v$database视图详解

SQL> desc v$database 名称 是否为空? 类型 ----------------- -------- ------------ DBID NUMBER NAME VARCHAR2(9) CREATED DATE RESETLOGS_CHANGE# NUMBER RESETLOGS_T…

大数据可视化设计到底是啥,该怎么用

大数据可视化是个热门话题&#xff0c;在信息安全领域&#xff0c;也由于很多企业希望将大数据转化为信息可视化呈现的各种形式&#xff0c;以便获得更深的洞察力、更好的决策力以及更强的自动化处理能力&#xff0c;数据可视化已经成为网络安全技术的一个重要趋势。文章目录一…

九度 1376 最近零子序列

http://ac.jobdu.com/problem.php?id1376 N^2的算法超时 优化算法想了好久没想出来&#xff0c;就当是学习一下STL的set了吧 1 #include <stdio.h> 2 #include <stdlib.h> 3 #include <math.h> 4 #include <set> 5 #include <iostream> 6 #defi…

WPF 如何实现颜色值拾取

WPF开发者QQ群&#xff1a; 340500857 前言如何进行颜色值拾取&#xff1f;这里采用的是调用WindowsAPI进行实现。吸取 沙漠尽头的狼 的建议多写一些文字进行描述。效果图如下&#xff1a;第一步 注册WindowsAPI 代码如下&#xff1a;[DllImport("user32.dll")]stati…

大文本导入mysql_大文本数据,导入导出到数据库

大文本数据&#xff0c;导入到数据库240w的数据&#xff0c;利用plsql的文本导入器&#xff0c;导了一个半小时&#xff0c;且数据出现缺失。两种方式导入到数据库一&#xff0c;使用sql load创建表create table ext_gv_tmp_amazon_sku(skucode varchar2(255 char),eancode var…

仿Google+相册的动画

在使用Google的时候&#xff0c;查看某一相册&#xff0c;会经常看到&#xff0c;如下图所示的动画效果。 鼠标移入、移出时均有动画效果&#xff0c;咋一看估计是使用了css3的transform属性来实现动画效果的。 在网上搜索“Google 相册 效果”的时候发现有人使用CSS3做了这样的…