记一次 .NET 某药材管理系统 卡死分析

心想事陈先生

一：背景

1. 讲故事

前段时间有位朋友找到我，说他们在查询报表的时候发现程序的稳定性会受到影响，但服务器的内存，CPU都是正常的，让我帮忙看下怎么回事，问了下程序的稳定性指的是什么？指的是卡死，那既然是卡死，就抓一个卡死的dump吧。
二：Windbg 分析

1. 当前是什么程序

不同的程序类型分析卡死的思路是不一样的，如果是 WKS模式 可以看下主线程，如果是 SRV模式 就要看其他线程了，接下来用 !eeversion 验证下。

1. 0:000> !eeversion
2. 5.0.521.16609 free
3. 5,0,521,16609 @Commit: 2f740adc1457e8a28c1c072993b66f515977eb51
4. Server mode with 16 gc heaps
5. SOS Version: 6.0.5.7301 retail build

复制代码

从卦中看当前是 .NET5 写的 Web网站，那就需要看其他线程都在做什么了。
2. 不稳定因素在哪里

朋友前面也说了查询报表的时候导致程序不稳定，因为这个因所以要找SQL查询的 果，大概率问题在数据库端，接下来使用 ~*e !clrstack 观察所有线程栈，输出如下：

1. OS Thread Id: 0x24e8 (60)
2.         Child SP               IP Call Site
3. 000000C2E3BFC700 00007ffd72955d04 [InlinedCallFrame: 000000c2e3bfc700] Microsoft.Data.SqlClient.SNINativeMethodWrapper.SNIReadSyncOverAsync(Microsoft.Data.SqlClient.SNIHandle, IntPtr ByRef, Int32)
4. 000000C2E3BFC700 00007ffce5e00264 [InlinedCallFrame: 000000c2e3bfc700] Microsoft.Data.SqlClient.SNINativeMethodWrapper.SNIReadSyncOverAsync(Microsoft.Data.SqlClient.SNIHandle, IntPtr ByRef, Int32)
5. 000000C2E3BFC6D0 00007ffce5e00264 ILStubClass.IL_STUB_PInvoke(Microsoft.Data.SqlClient.SNIHandle, IntPtr ByRef, Int32)
6. 000000C2E3BFC7A0 00007ffce7a3ca1f Microsoft.Data.SqlClient.TdsParserStateObjectNative.ReadSyncOverAsync(Int32, UInt32 ByRef)
7. 000000C2E3BFC7F0 00007ffce7a3c72c Microsoft.Data.SqlClient.TdsParserStateObject.ReadSniSyncOverAsync()
8. 000000C2E3BFC880 00007ffce7a3c60b Microsoft.Data.SqlClient.TdsParserStateObject.TryReadNetworkPacket()
9. 000000C2E3BFC8C0 00007ffce7a3c53e Microsoft.Data.SqlClient.TdsParserStateObject.TryPrepareBuffer()
10. 000000C2E3BFC900 00007ffce79de54e Microsoft.Data.SqlClient.TdsParserStateObject.TryReadByte(Byte ByRef)
11. 000000C2E3BFC940 00007ffce5e06bce Microsoft.Data.SqlClient.TdsParser.TryRun(Microsoft.Data.SqlClient.RunBehavior, Microsoft.Data.SqlClient.SqlCommand, Microsoft.Data.SqlClient.SqlDataReader, Microsoft.Data.SqlClient.BulkCopySimpleResultSet, Microsoft.Data.SqlClient.TdsParserStateObject, Boolean ByRef)
12. 000000C2E3BFCAE0 00007ffce5e38d51 Microsoft.Data.SqlClient.SqlDataReader.TryConsumeMetaData()
13. 000000C2E3BFCB50 00007ffce7a94f77 Microsoft.Data.SqlClient.SqlDataReader.get_MetaData()
14. ....
16. OS Thread Id: 0x854 (72)
17.         Child SP               IP Call Site
18. 000000C2E66BBE70 00007ffd72955d04 [InlinedCallFrame: 000000c2e66bbe70] Microsoft.Data.SqlClient.SNINativeMethodWrapper.SNIReadSyncOverAsync(Microsoft.Data.SqlClient.SNIHandle, IntPtr ByRef, Int32)
19. 000000C2E66BBE70 00007ffce5e00264 [InlinedCallFrame: 000000c2e66bbe70] Microsoft.Data.SqlClient.SNINativeMethodWrapper.SNIReadSyncOverAsync(Microsoft.Data.SqlClient.SNIHandle, IntPtr ByRef, Int32)
20. 000000C2E66BBE40 00007ffce5e00264 ILStubClass.IL_STUB_PInvoke(Microsoft.Data.SqlClient.SNIHandle, IntPtr ByRef, Int32)
21. 000000C2E66BBF10 00007ffce7a3ca1f Microsoft.Data.SqlClient.TdsParserStateObjectNative.ReadSyncOverAsync(Int32, UInt32 ByRef)
22. 000000C2E66BBF60 00007ffce7a3c72c Microsoft.Data.SqlClient.TdsParserStateObject.ReadSniSyncOverAsync()
23. 000000C2E66BBFF0 00007ffce7a3c60b Microsoft.Data.SqlClient.TdsParserStateObject.TryReadNetworkPacket()
24. 000000C2E66BC030 00007ffce7a3c53e Microsoft.Data.SqlClient.TdsParserStateObject.TryPrepareBuffer()
25. 000000C2E66BC070 00007ffce79de54e Microsoft.Data.SqlClient.TdsParserStateObject.TryReadByte(Byte ByRef)
26. 000000C2E66BC0B0 00007ffce5e06bce Microsoft.Data.SqlClient.TdsParser.TryRun(Microsoft.Data.SqlClient.RunBehavior, Microsoft.Data.SqlClient.SqlCommand, Microsoft.Data.SqlClient.SqlDataReader, Microsoft.Data.SqlClient.BulkCopySimpleResultSet, Microsoft.Data.SqlClient.TdsParserStateObject, Boolean ByRef)
27. 000000C2E66BC250 00007ffce5e38d51 Microsoft.Data.SqlClient.SqlDataReader.TryConsumeMetaData()
28. 000000C2E66BC2C0 00007ffce7a94f77 Microsoft.Data.SqlClient.SqlDataReader.get_MetaData()
29. ...

复制代码

从卦中看当前有两个线程在请求SQLSERVER，并在等待返回结果，接下来问题就来了，既然说卡死肯定花费了不少时间，所以对当前是什么 SQL 产生了好奇，我们可以提取下 72 号线程的 SqlCommand 对象，看看是什么sql？

1. 0:072> !dso
2. OS Thread Id: 0x854 (72)
3. RSP/REG          Object           Name
4. 000000C2E66BBDC8 00000216eafe2520 Microsoft.Data.SqlClient.SqlCommand
6. 0:072> !DumpObj /d 00000216eafe2520
7. Name:        Microsoft.Data.SqlClient.SqlCommand
8. 00007ffce4027a90  400046d       18        System.String  0 instance 00000216eafe1a60 _commandText

复制代码

然后 do 一下 _commandText 就可以了，去敏之后的SQL如下；

1. SELECT xxx
2. FROM [xxxxxx] AS [d]
3. LEFT JOIN [xxxDrugs] AS [n]
4.     ON [d].[DrugId] = [n].[xxx]
5. WHERE [d].[xxxId] = '4f1be71f-2edb-4a5c-87dc-9ab3b981cbca'

复制代码

上面的sql也就一个简单的表关联，但我的职业敏感性告诉我，这条sql应该就是没加 nolock 导致在 SQLSERVER 层面一直获取不到 S 锁，获取不到 S 锁的原因应该就是 报表 间接导致很多的意向U和意向X在相关表上成了 U 和 X 锁。
3. 到底卡了多久

怀疑是 SQLSERVER 层面的问题后，接下来还要找证据验证一下，也就是当前这条SQL到底阻塞了多久？ 那怎么在 Dump 中观察 SQL 的请求时间呢？这就需要考察你对  SQLConnection 类的理解了，其中有一个字段 SqlConnection._innerConnection._createTime._dateData 就记录了 SQL 的开始时间。

1. 0:072> !DumpObj /d 00000216eaf85fa0
2. Name:        Microsoft.Data.SqlClient.SqlConnection
3. 00007ffce61bb9f8  40004c6       90 ...onnectionInternal  0 instance 00000215cad017c0 _innerConnection
5. 0:072> !DumpObj /d 00000215cad017c0
6. Name:        Microsoft.Data.SqlClient.SqlInternalConnectionTds
7. 00007ffce42c7670  4000174       48      System.DateTime  1 instance 00000215cad01808 _createTime
9. 0:072> !DumpVC /d 00007ffce42c7670 00000215cad01808
10. Name:        System.DateTime
11. Fields:
12.               MT    Field   Offset                 Type VT     Attr            Value Name
13. 00007ffce3f6cf98  4000258        0        System.UInt64  1 instance 5249873640594058230 _dateData

复制代码

卦中的 0n5249873640594058230 怎么转化为具体时间呢？这又是考验你的基础知识了，这个数的前两位bit记录的是 时区信息 ，比如本地还是UTC，参考代码如下：

1.         internal DateTime(long ticks, DateTimeKind kind, bool isAmbiguousDst)
2.         {
3.             if (ticks < 0 || ticks > 3155378975999999999L)
4.             {
5.                 throw new ArgumentOutOfRangeException("ticks", SR.ArgumentOutOfRange_DateTimeBadTicks);
6.             }
7.             _dateData = (ulong)ticks | (isAmbiguousDst ? 13835058055282163712uL : 9223372036854775808uL);
8.         }

复制代码

上面的两个超大十进制数转化为二进制即高位的 11 和 10 开头，也就是十六进制开头的 c 和 8 。

1. 0:072> ? 0n13835058055282163712
2. Evaluate expression: -4611686018427387904 = c0000000`00000000
4. 0:072> ? 0n9223372036854775808
5. Evaluate expression: -9223372036854775808 = 80000000`00000000

复制代码

那怎么将 _dateData 转成 ticks 呢？在源码中也有说明，即抹掉二进制中的高二位。

1.         internal long InternalTicks => (long)(_dateData & 0x3FFFFFFFFFFFFFFFL);

复制代码

有了这些前置基础，接下来就可以用 windbg 转换了。

1. 0:072> ? 0n5249873640594058230 & 0x3FFFFFFFFFFFFFFF
2. Evaluate expression: 638187622166670326 = 08db4c42`d74babf6
4. 0:072> .formats 08db4c42`d74babf6
5. Evaluate expression:
6.   Hex:     08db4c42`d74babf6
7.   Decimal: 638187622166670326
8.   Decimal (unsigned) : 638187622166670326
9.   Octal:   0043332304132722725766
10.   Binary:  00001000 11011011 01001100 01000010 11010111 01001011 10101011 11110110
11.   Chars:   ..LB.K..
12.   Time:    Thu May  4 09:56:56.667 3623 (UTC + 8:00)
13.   Float:   low -2.23939e+014 high 1.31985e-033
14.   Double:  5.29119e-266
16. 0:072> .time
17. Debug session time: Thu May  4 09:58:39.000 2023 (UTC + 8:00)
18. System Uptime: 40 days 10:15:42.713
19. Process Uptime: 0 days 16:55:48.000
20.   Kernel time: 0 days 0:01:54.000
21.   User time: 0 days 0:39:40.000

复制代码

从卦中看，SQL 的请求时间是 09:56:56 ，Dump抓取时间为 09:58:39，也就表示当前这条 SQL 已经等待了 1分43秒，这确实是不可容忍的。
从 dump 中挖到这些信息后，让朋友重点观察下 SQLSERVER 端，比如在卡住的时候查下锁相关的 DMV视图，是不是出现了锁等待，也可以加上 nolock 尝试一下。
最终朋友在 SQLSERVER 层面修改了 max degree of parallelism 来提高并发度，说情况缓解了很多，这其中细节，熟悉 SQLSERVER 的朋友可以留言解答一下哈。
三：总结

这次不稳定的事故从直观上就能猜到可能是 SQLSERVER 层面导致的问题，但需要证据，所以我们需要用 windbg 在这小小的花园里，挖呀挖呀挖！ 让朋友对外有数据层面的说服力。

来源:https://www.cnblogs.com/huangxincheng/archive/2023/06/15/17483537.html
免责声明：由于采集信息均来自互联网，如果侵犯了您的权益，请联系我们【E-Mail:cb@itdo.tech】 我们会及时删除侵权内容，谢谢合作！