记一次 某智能制造MES系统CPU 爆高分析

一次,智能,制造,mes,系统,cpu,分析 · 浏览次数 : 2013

小编点评

**问题** 如何解决利用某商业数据访问sdk 在异常参数处理时逻辑不严谨所致的问题? **解决方案** 1. **明确异常处理逻辑** - 抛出异常时,明确异常处理逻辑,例如将异常信息抛出到异常处理类中进行处理。 2. **处理异常参数** - 当异常参数被处理时,进行逻辑处理,例如将异常参数值绑定到异常参数中进行处理。 3. **异常捕获** - 在异常捕获过程中,捕获异常信息,并进行异常处理,例如将异常信息抛出到异常处理类中进行处理。 4. **异常日志记录** - 在异常捕获和处理过程中,记录异常信息,以便日志记录分析。 5. **异常处理类设计** - 设计异常处理类,并实现异常处理逻辑,例如将异常信息抛出到异常处理类中进行处理。 6. **异常通知机制** - 在异常处理中,设置异常通知机制,例如将异常信息通知到异常处理类中进行处理。 7. **异常日志记录** - 在异常处理和日志记录中,记录异常信息,以便日志记录分析。

正文

一:背景

1. 讲故事

前段时间有位朋友找到我,说他 docker 中的web服务深夜cpu被打满,让我帮忙看一下,很多朋友问docker中怎么抓dump,我一般都推荐使用 procdump 这款自动化工具,谁用谁知道,有了 dump 之后,接下来就是分析了。

二:WinDbg 分析

1. cpu 真的爆高吗

有很多朋友问 linux 上的dump可以用 windbg 分析吗?这里统一回复下,是可以的,现在的 WinDbg 可以全平台分析,不信看下图:

不过有一点吐槽的是,Linux 不是微软的,所以在 操作系统层级 上的调试支持是不够的,也不是 WinDbg 能力所触及范围之内,所以相比 Windows 有很多的不便。

接下来我们用 !tp 看一下当前的 cpu 到底是多少?


0:000> !tp
CPU utilization: 393 %
Worker Thread: Total: 19 Running: 5 Idle: 10 MaxLimit: 32767 MinLimit: 4
Work Request in Queue: 0
--------------------------------------
Number of Timers: 4
--------------------------------------
Completion Port Thread:Total: 0 Free: 0 MaxFree: 8 CurrentLimit: 0 MaxLimit: 1000 MinLimit: 4

从卦中看当前的 cpu=393% ,这表示什么意思呢?在Linux上是这样的,一个核占用 100%,可以理解成当前有 4 个核被打满。

那当前 docker 中给了多少 cpu 核呢?在 Windows 平台上可以用 !cpuid,在 Linux 上肯定用不了了,没关系,熟悉 CLR 的朋友应该知道,ServerGC 的heap个数默认按照cpu 的个数来的,也就是说当前多少个heap,也就有多少个 cpu core。

有了这个思路,使用 !eeversion 来看下 gc 模式吧。


0:000> !eeversion
4.700.21.56803 (3.x runtime)
4.700.21.56803 @Commit: 28bb6f994c28bc91f09bc0ddb5dcb51d0f066806
Server mode with 4 gc heaps
SOS Version: 7.0.8.10101 retail build

从卦中的 Server mode with 4 gc heaps 来看,当前docker使用 4 个 cpu 核,所以 393% 就表示了当前被完全打满。

2. 为什么会被打满

一般来说cpu的跌宕起伏都是由 thread 诱发的,一个好的思路就是看下此时各个线程都在做什么,可以使用 ~*e !clrstack 观察,经过仔细对比发现有 4 处 SqlDataReader 貌似在读什么东西,刚好对应到了 CPU 核数,输出如下:


0:000> ~*e !clrstack
OS Thread Id: 0x3f89 (24)
        Child SP               IP Call Site
00007F9FA14A0628 00007fa4803e2a93 System.Data.SqlClient.TdsParser.TrySkipValue(System.Data.SqlClient.SqlMetaDataPriv, Int32, System.Data.SqlClient.TdsParserStateObject) [/_/src/System.Data.SqlClient/src/System/Data/SqlClient/TdsParser.cs @ 4399]
00007F9FA14A0640 00007fa47f9a5e03 System.Data.SqlClient.TdsParser.TrySkipRow(System.Data.SqlClient._SqlMetaDataSet, Int32, System.Data.SqlClient.TdsParserStateObject) [/_/src/System.Data.SqlClient/src/System/Data/SqlClient/TdsParser.cs @ 4334]
00007F9FA14A0670 00007fa4803d2fba System.Data.SqlClient.SqlDataReader.TryCleanPartialRead() [/_/src/System.Data.SqlClient/src/System/Data/SqlClient/SqlDataReader.cs @ 760]
00007F9FA14A0690 00007fa47f99e424 System.Data.SqlClient.SqlDataReader.TryReadInternal(Boolean, Boolean ByRef) [/_/src/System.Data.SqlClient/src/System/Data/SqlClient/SqlDataReader.cs @ 3286]
00007F9FA14A06F0 00007fa4804742e5 System.Data.SqlClient.SqlDataReader+c__DisplayClass190_0.b__1(System.Threading.Tasks.Task) [/_/src/System.Data.SqlClient/src/System/Data/SqlClient/SqlDataReader.cs @ 4448]
00007F9FA14A0720 00007fa480a239ea System.Data.SqlClient.SqlDataReader+c__DisplayClass194_0`1[[System.Boolean, System.Private.CoreLib]].b__0(System.Threading.Tasks.Task`1<System.Object>) [/_/src/System.Data.SqlClient/src/System/Data/SqlClient/SqlDataReader.cs @ 4804]
00007F9FA14A0770 00007fa4803fa6ce System.Threading.Tasks.ContinuationResultTaskFromResultTask`2[[System.__Canon, System.Private.CoreLib],[System.__Canon, System.Private.CoreLib]].InnerInvoke() [/_/src/System.Private.CoreLib/shared/System/Threading/Tasks/TaskContinuation.cs @ 191]
00007F9FA14A07B0 00007fa4803d5551 System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(System.Threading.Thread, System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) [/_/src/System.Private.CoreLib/shared/System/Threading/ExecutionContext.cs @ 315]
00007F9FA14A07F0 00007fa4803d1c2c System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef, System.Threading.Thread) [/_/src/System.Private.CoreLib/shared/System/Threading/Tasks/Task.cs @ 2421]
00007F9FA14A0870 00007fa4803b99a9 System.Threading.ThreadPoolWorkQueue.Dispatch() [/_/src/System.Private.CoreLib/shared/System/Threading/ThreadPool.cs @ 699]
00007F9FA14A0C80 00007fa4f11512df [DebuggerU2MCatchHandlerFrame: 00007f9fa14a0c80] 
OS Thread Id: 0x3f8a (25)
        Child SP               IP Call Site
00007F9FA3154580 00007fa4803bc857 System.Data.SqlClient.TdsParser.TryGetTokenLength(Byte, System.Data.SqlClient.TdsParserStateObject, Int32 ByRef) [/_/src/System.Data.SqlClient/src/System/Data/SqlClient/TdsParser.cs @ 5889]
...
00007F9FA3154670 00007fa4803d2fba System.Data.SqlClient.SqlDataReader.TryCleanPartialRead() [/_/src/System.Data.SqlClient/src/System/Data/SqlClient/SqlDataReader.cs @ 760]
00007F9FA3154690 00007fa47f99e424 System.Data.SqlClient.SqlDataReader.TryReadInternal(Boolean, Boolean ByRef) [/_/src/System.Data.SqlClient/src/System/Data/SqlClient/SqlDataReader.cs @ 3286]
...
00007F9FA3154870 00007fa4803b99a9 System.Threading.ThreadPoolWorkQueue.Dispatch() [/_/src/System.Private.CoreLib/shared/System/Threading/ThreadPool.cs @ 699]
00007F9FA3154C80 00007fa4f11512df [DebuggerU2MCatchHandlerFrame: 00007f9fa3154c80] 
OS Thread Id: 0x5211 (37)
        Child SP               IP Call Site
00007F9FD2FFC570 00007fa4803bc921 System.Data.SqlClient.TdsParserStateObject.TryReadUInt16(UInt16 ByRef) [/_/src/System.Data.SqlClient/src/System/Data/SqlClient/TdsParserStateObject.cs @ 1519]
00007F9FD2FFC580 00007fa4803bc891 System.Data.SqlClient.TdsParser.TryGetTokenLength(Byte, System.Data.SqlClient.TdsParserStateObject, Int32 ByRef) [/_/src/System.Data.SqlClient/src/System/Data/SqlClient/TdsParser.cs @ 5889]
00007F9FD2FFC5C0 00007fa4803e2c06 System.Data.SqlClient.TdsParser.TrySkipValue(System.Data.SqlClient.SqlMetaDataPriv, Int32, System.Data.SqlClient.TdsParserStateObject) [/_/src/System.Data.SqlClient/src/System/Data/SqlClient/TdsParser.cs @ 4399]
00007F9FD2FFC640 00007fa47f9a5e03 System.Data.SqlClient.TdsParser.TrySkipRow(System.Data.SqlClient._SqlMetaDataSet, Int32, System.Data.SqlClient.TdsParserStateObject) [/_/src/System.Data.SqlClient/src/System/Data/SqlClient/TdsParser.cs @ 4334]
...
00007F9FD2FFC870 00007fa4803b99a9 System.Threading.ThreadPoolWorkQueue.Dispatch() [/_/src/System.Private.CoreLib/shared/System/Threading/ThreadPool.cs @ 699]
00007F9FD2FFCC80 00007fa4f11512df [DebuggerU2MCatchHandlerFrame: 00007f9fd2ffcc80] 
OS Thread Id: 0x5212 (38)
        Child SP               IP Call Site
00007F9FB3FFE580 00007fa4803bc839 System.Data.SqlClient.TdsParser.TryGetTokenLength(Byte, System.Data.SqlClient.TdsParserStateObject, Int32 ByRef) [/_/src/System.Data.SqlClient/src/System/Data/SqlClient/TdsParser.cs @ 5889]
00007F9FB3FFE5C0 00007fa4803e2c06 System.Data.SqlClient.TdsParser.TrySkipValue(System.Data.SqlClient.SqlMetaDataPriv, Int32, System.Data.SqlClient.TdsParserStateObject) [/_/src/System.Data.SqlClient/src/System/Data/SqlClient/TdsParser.cs @ 4399]
00007F9FB3FFE640 00007fa47f9a5e03 System.Data.SqlClient.TdsParser.TrySkipRow(System.Data.SqlClient._SqlMetaDataSet, Int32, System.Data.SqlClient.TdsParserStateObject) [/_/src/System.Data.SqlClient/src/System/Data/SqlClient/TdsParser.cs @ 4334]
00007F9FB3FFE670 00007fa4803d2fba System.Data.SqlClient.SqlDataReader.TryCleanPartialRead() [/_/src/System.Data.SqlClient/src/System/Data/SqlClient/SqlDataReader.cs @ 760]
...
00007F9FB3FFE7F0 00007fa4803d1c2c System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef, System.Threading.Thread) [/_/src/System.Private.CoreLib/shared/System/Threading/Tasks/Task.cs @ 2421]
00007F9FB3FFE870 00007fa4803b99a9 System.Threading.ThreadPoolWorkQueue.Dispatch() [/_/src/System.Private.CoreLib/shared/System/Threading/ThreadPool.cs @ 699]
00007F9FB3FFEC80 00007fa4f11512df [DebuggerU2MCatchHandlerFrame: 00007f9fb3ffec80] 

从卦中看,虽然异步写的很爽,可逆向分析起来真的是上刀山下火海。。。 接下来思路在哪里呢?可以这么想,既然是和 SqlDataReader 有关系,那就挖一挖,看看里面有什么sql。


0:025> !dso
OS Thread Id: 0x3f8a (25)
RSP/REG          Object           Name
rdx              00007fa128ad9c08 System.Data.SqlClient.SNI.TdsParserStateObjectManaged
rdi              00007fa128ad9c08 System.Data.SqlClient.SNI.TdsParserStateObjectManaged
r9               00007fa128ad9c08 System.Data.SqlClient.SNI.TdsParserStateObjectManaged
r12              00007fa128ad9c08 System.Data.SqlClient.SNI.TdsParserStateObjectManaged
r13              00007fa128ad9b70 System.Data.SqlClient.TdsParser
...
00007F9FA31546B0 00007fa3297b8fb8 System.Data.SqlClient.SqlDataReader
...

0:025> !DumpObj /d 00007fa3297b84d0
Name:        System.String
MethodTable: 00007fa477db0f90
EEClass:     00007fa477d1e230
Size:        2496(0x9c0) bytes
File:        /usr/share/dotnet/shared/Microsoft.NETCore.App/3.1.22/System.Private.CoreLib.dll
String:      select xxx,xxx,xxx,xxx from template_xxxreport where 1=1 
Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
00007fa477daa0e8  400022a        8         System.Int32  1 instance             1237 _stringLength
00007fa477da6f00  400022b        c          System.Char  1 instance               73 _firstChar
00007fa477db0f90  400022c      108        System.String  0   static 00007fa027fff360 Empty

从 sql 看貌似是读了 template_xxxreport 表, 而且还没有筛选条件,看样子是深夜跑什么数据把 CPU 给抬起来了,那接下里的问题是什么地方会执行这条sql呢?

3. 到底在哪里执行的

刚才的线程栈看不到一句用户代码,我们还可以用 !gcroot 追踪下这个 sql 的祖宗,可能会有新的发现哦。


0:025> !gcroot 00007fa3297b84d0
    00007F9FA3154770 00007FA4803FA6CE System.Threading.Tasks.ContinuationResultTaskFromResultTask`2[[System.__Canon, System.Private.CoreLib],[System.__Canon, System.Private.CoreLib]].InnerInvoke() [/_/src/System.Private.CoreLib/shared/System/Threading/Tasks/TaskContinuation.cs @ 191]
        rbx: 
            ->  00007FA233579680 System.Threading.Tasks.ContinuationResultTaskFromResultTask`2[[System.Object, System.Private.CoreLib],[System.Threading.Tasks.Task`1[[System.Boolean, System.Private.CoreLib]], System.Private.CoreLib]]
            ->  00007FA233579748 System.Threading.Tasks.UnwrapPromise`1[[System.Boolean, System.Private.CoreLib]]
            ...
            ->  00007FA329BE4BB0 System.Threading.Tasks.StandardTaskContinuation
            ->  00007FA329BE4B18 System.Threading.Tasks.ContinuationTaskFromResultTask`1[[System.Boolean, System.Private.CoreLib]]
            ->  00007FA329BE4AD8 System.Action`1[[System.Threading.Tasks.Task`1[[System.Boolean, System.Private.CoreLib]], System.Private.CoreLib]]
            ->  00007FA329BE2AE8 System.Data.SqlClient.SqlDataReader+<>c__DisplayClass195_0`1[[System.Boolean, System.Private.CoreLib]]
            ->  00007FA32982AE50 System.Threading.Tasks.TaskCompletionSource`1[[System.Boolean, System.Private.CoreLib]]
            ->  00007FA32982AE68 System.Threading.Tasks.Task`1[[System.Boolean, System.Private.CoreLib]]
            ->  00007FA3297B91B0 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[xxx.xxx.Template_xxxxReport, xxx.xxx],[Dapper.SqlMapper+<QueryRowAsync>d__34`1[[xxx.xxxx.Template_xxxxReport, xxx.xxxx]], Dapper]]
            ->  00007FA3297B84D0 System.String

从引用链条看,这条sql使用 Dapper 的 QueryRowAsync 查询,实体类是 xxx.xxxx.Template_xxxxReport,有了这些信息就好办了,反馈给朋友后,让朋友看下这是哪里的sql和model。

据朋友调查后,说是用的某商业数据访问sdk 内部逻辑不严谨造成的,参考代码如下:


    public async Task<T> FindEntity<T>(object param) where T : class
    {
        //核心问题
        if (param == null)
        {
            param = new { };
        }

        var parameters = param.ToObject();

        //参数拼接
        foreach (var item in parameters)
        {
            // xxxxx
        }
    }

param =null 时,底层用 param = new { }; 当无参数处理,这就导致全表sql的发生,朋友说现在想想都有点后怕。。。

三:总结

这次事故主要是由 某商业数据访问sdk 在异常参数处理时逻辑不严谨所致,毕竟 抛异常全量查询 要好得多,大家在买商业组件的时候,且行且珍惜。
图片名称

与记一次 某智能制造MES系统CPU 爆高分析相似的内容:

记一次 某智能制造MES系统CPU 爆高分析

一:背景 1. 讲故事 前段时间有位朋友找到我,说他 docker 中的web服务深夜cpu被打满,让我帮忙看一下,很多朋友问docker中怎么抓dump,我一般都推荐使用 procdump 这款自动化工具,谁用谁知道,有了 dump 之后,接下来就是分析了。 二:WinDbg 分析 1. cpu

记一次 .NET某上位视觉程序 离奇崩溃分析

一:背景 1. 讲故事 前段时间有位朋友找到我,说他们有一个崩溃的dump让我帮忙看下怎么回事,确实有太多的人在网上找各种故障分析最后联系到了我,还好我一直都是免费分析,不收取任何费用,造福社区。 话不多说,既然有 dump 来了,那就上 windbg 说话吧。 二:WinDbg 分析 1. 为什么

记一次 .NET某酒业业务系统 崩溃分析

一:背景 1. 讲故事 前些天有位朋友找到我,说他的程序每次关闭时就会自动崩溃,一直找不到原因让我帮忙看一下怎么回事,这位朋友应该是第二次找我了,分析了下 dump 还是挺经典的,拿出来给大家分享一下吧。 二:WinDbg 分析 1. 为什么会崩溃 找崩溃原因比较简单,用 !analyze -v 命

记一次 .NET某网络边缘计算系统 卡死分析

一:背景 1. 讲故事 早就听说过有什么 网络边缘计算,这次还真给遇到了,有点意思,问了下 chatgpt 这是干嘛的 ? 网络边缘计算是一种计算模型,它将计算能力和数据存储位置从传统的集中式数据中心向网络边缘的用户设备、传感器和其他物联网设备移动。这种模型的目的是在接近数据生成源头的地方提供更快速

记一次 .NET某机械臂上位系统 卡死分析

一:背景 1. 讲故事 前些天有位朋友找到我,说他们的程序会偶发性的卡死一段时间,然后又好了,让我帮忙看下怎么回事?窗体类的程序解决起来相对来说比较简单,让朋友用procdump自动抓一个卡死时的dump,拿到dump之后,上 windbg 说话。 二:WinDbg 分析 1. 主线程在做什么 要想

记一次 .NET某工厂报警监控设置 崩溃分析

一:背景 1. 讲故事 前些天有位朋友在微信上丢了一个崩溃的dump给我,让我帮忙看下为什么出现了崩溃,在 Windows 的事件查看器上显示的是经典的 访问违例 ,即 c0000005 错误码,不管怎么说有dump就可以上windbg开干了。 二:WinDbg 分析 1. 程序为谁崩溃了 在 Wi

记一次 .NET某游戏币自助机后端 内存暴涨分析

一:背景 1. 讲故事 前些天有位朋友找到我,说他们的程序内存会偶发性暴涨,自己分析了下是非托管内存问题,让我帮忙看下怎么回事?哈哈,看到这个dump我还是非常有兴趣的,居然还有这种游戏币自助机类型的程序,下次去大玩家看看他们出币的机器后端是不是C#写的?由于dump是linux上的程序,刚好win

记一次 .NET某工控视觉自动化系统 卡死分析

一:背景 1. 讲故事 今天分享的dump是训练营里一位学员的,从一个啥也不会到现在分析的有模有样,真的是看他成长起来的,调试技术学会了就是真真实实自己的,话不多说,上windbg说话。 二:WinDbg 分析 1. 为什么会卡死 这位学员是从事工控大类下的视觉自动化,也是目前.NET的主战场,这个

记一次 .NET某质量检测中心系统 崩溃分析

一:背景 1. 讲故事 这些天有点意思,遇到的几个程序故障都是和Windows操作系统或者第三方组件有关系,真的有点无语,今天就带给大家一例 IIS 相关的与大家分享,这是一家国企的.NET程序,出现了崩溃急需分析。 二:WinDbg 分析 1. 为什么会崩溃 崩溃原因相对还是好找的,双击dump文

记一次 .NET某工业设计软件 崩溃分析

一:背景 1. 讲故事 前些天有位朋友找到我,说他的软件在客户那边不知道什么原因崩掉了,从windows事件日志看崩溃在 clr 里,让我能否帮忙定位下,dump 也抓到了,既然dump有了,接下来就上 windbg 分析吧。 二:WinDbg 分析 1. 为什么崩溃在 clr 一般来说崩溃在clr