技術文章 » 記一次 .NET 某藥材管理系統 卡死分析

記一次 .NET 某藥材管理系統 卡死分析

2023-06-15 18:00:45

一：背景

1. 講故事

前段時間有位朋友找到我，說他們在查詢報表的時候發現程式的穩定性會受到影響，但伺服器的記憶體，CPU都是正常的，讓我幫忙看下怎麼回事，問了下程式的穩定性指的是什麼？指的是卡死，那既然是卡死，就抓一個卡死的dump吧。

二：Windbg 分析

1. 當前是什麼程式

不同的程式型別分析卡死的思路是不一樣的，如果是 WKS模式 可以看下主執行緒，如果是 SRV模式 就要看其他執行緒了，接下來用 !eeversion 驗證下。


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

從卦中看當前是 .NET5 寫的 Web網站，那就需要看其他執行緒都在做什麼了。

2. 不穩定因素在哪裡

朋友前面也說了查詢報表的時候導致程式不穩定，因為這個因所以要找SQL查詢的 果，大概率問題在資料庫端，接下來使用 ~*e !clrstack 觀察所有執行緒棧，輸出如下：


OS Thread Id: 0x24e8 (60)
        Child SP               IP Call Site
000000C2E3BFC700 00007ffd72955d04 [InlinedCallFrame: 000000c2e3bfc700] Microsoft.Data.SqlClient.SNINativeMethodWrapper.SNIReadSyncOverAsync(Microsoft.Data.SqlClient.SNIHandle, IntPtr ByRef, Int32)
000000C2E3BFC700 00007ffce5e00264 [InlinedCallFrame: 000000c2e3bfc700] Microsoft.Data.SqlClient.SNINativeMethodWrapper.SNIReadSyncOverAsync(Microsoft.Data.SqlClient.SNIHandle, IntPtr ByRef, Int32)
000000C2E3BFC6D0 00007ffce5e00264 ILStubClass.IL_STUB_PInvoke(Microsoft.Data.SqlClient.SNIHandle, IntPtr ByRef, Int32)
000000C2E3BFC7A0 00007ffce7a3ca1f Microsoft.Data.SqlClient.TdsParserStateObjectNative.ReadSyncOverAsync(Int32, UInt32 ByRef)
000000C2E3BFC7F0 00007ffce7a3c72c Microsoft.Data.SqlClient.TdsParserStateObject.ReadSniSyncOverAsync()
000000C2E3BFC880 00007ffce7a3c60b Microsoft.Data.SqlClient.TdsParserStateObject.TryReadNetworkPacket()
000000C2E3BFC8C0 00007ffce7a3c53e Microsoft.Data.SqlClient.TdsParserStateObject.TryPrepareBuffer()
000000C2E3BFC900 00007ffce79de54e Microsoft.Data.SqlClient.TdsParserStateObject.TryReadByte(Byte ByRef)
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)
000000C2E3BFCAE0 00007ffce5e38d51 Microsoft.Data.SqlClient.SqlDataReader.TryConsumeMetaData()
000000C2E3BFCB50 00007ffce7a94f77 Microsoft.Data.SqlClient.SqlDataReader.get_MetaData()
....

OS Thread Id: 0x854 (72)
        Child SP               IP Call Site
000000C2E66BBE70 00007ffd72955d04 [InlinedCallFrame: 000000c2e66bbe70] Microsoft.Data.SqlClient.SNINativeMethodWrapper.SNIReadSyncOverAsync(Microsoft.Data.SqlClient.SNIHandle, IntPtr ByRef, Int32)
000000C2E66BBE70 00007ffce5e00264 [InlinedCallFrame: 000000c2e66bbe70] Microsoft.Data.SqlClient.SNINativeMethodWrapper.SNIReadSyncOverAsync(Microsoft.Data.SqlClient.SNIHandle, IntPtr ByRef, Int32)
000000C2E66BBE40 00007ffce5e00264 ILStubClass.IL_STUB_PInvoke(Microsoft.Data.SqlClient.SNIHandle, IntPtr ByRef, Int32)
000000C2E66BBF10 00007ffce7a3ca1f Microsoft.Data.SqlClient.TdsParserStateObjectNative.ReadSyncOverAsync(Int32, UInt32 ByRef)
000000C2E66BBF60 00007ffce7a3c72c Microsoft.Data.SqlClient.TdsParserStateObject.ReadSniSyncOverAsync()
000000C2E66BBFF0 00007ffce7a3c60b Microsoft.Data.SqlClient.TdsParserStateObject.TryReadNetworkPacket()
000000C2E66BC030 00007ffce7a3c53e Microsoft.Data.SqlClient.TdsParserStateObject.TryPrepareBuffer()
000000C2E66BC070 00007ffce79de54e Microsoft.Data.SqlClient.TdsParserStateObject.TryReadByte(Byte ByRef)
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)
000000C2E66BC250 00007ffce5e38d51 Microsoft.Data.SqlClient.SqlDataReader.TryConsumeMetaData()
000000C2E66BC2C0 00007ffce7a94f77 Microsoft.Data.SqlClient.SqlDataReader.get_MetaData()
...

從卦中看當前有兩個執行緒在請求SQLSERVER，並在等待返回結果，接下來問題就來了，既然說卡死肯定花費了不少時間，所以對當前是什麼 SQL 產生了好奇，我們可以提取下 72 號執行緒的 SqlCommand 物件，看看是什麼sql？


0:072> !dso
OS Thread Id: 0x854 (72)
RSP/REG          Object           Name
000000C2E66BBDC8 00000216eafe2520 Microsoft.Data.SqlClient.SqlCommand

0:072> !DumpObj /d 00000216eafe2520
Name:        Microsoft.Data.SqlClient.SqlCommand
00007ffce4027a90  400046d       18        System.String  0 instance 00000216eafe1a60 _commandText

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


SELECT xxx
FROM [xxxxxx] AS [d]
LEFT JOIN [xxxDrugs] AS [n]
    ON [d].[DrugId] = [n].[xxx]
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 的開始時間。


0:072> !DumpObj /d 00000216eaf85fa0
Name:        Microsoft.Data.SqlClient.SqlConnection
00007ffce61bb9f8  40004c6       90 ...onnectionInternal  0 instance 00000215cad017c0 _innerConnection

0:072> !DumpObj /d 00000215cad017c0
Name:        Microsoft.Data.SqlClient.SqlInternalConnectionTds
00007ffce42c7670  4000174       48      System.DateTime  1 instance 00000215cad01808 _createTime

0:072> !DumpVC /d 00007ffce42c7670 00000215cad01808
Name:        System.DateTime
Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
00007ffce3f6cf98  4000258        0        System.UInt64  1 instance 5249873640594058230 _dateData

卦中的 0n5249873640594058230 怎麼轉化為具體時間呢？這又是考驗你的基礎知識了，這個數的前兩位bit記錄的是 時區資訊 ，比如本地還是UTC，參考程式碼如下：


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

上面的兩個超大十進位制數轉化為二進位制即高位的 11 和 10 開頭，也就是十六進位制開頭的 c 和 8 。


0:072> ? 0n13835058055282163712
Evaluate expression: -4611686018427387904 = c0000000`00000000

0:072> ? 0n9223372036854775808
Evaluate expression: -9223372036854775808 = 80000000`00000000

那怎麼將 _dateData 轉成 ticks 呢？在原始碼中也有說明，即抹掉二進位制中的高二位。


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

有了這些前置基礎，接下來就可以用 windbg 轉換了。


0:072> ? 0n5249873640594058230 & 0x3FFFFFFFFFFFFFFF
Evaluate expression: 638187622166670326 = 08db4c42`d74babf6

0:072> .formats 08db4c42`d74babf6
Evaluate expression:
  Hex:     08db4c42`d74babf6
  Decimal: 638187622166670326
  Decimal (unsigned) : 638187622166670326
  Octal:   0043332304132722725766
  Binary:  00001000 11011011 01001100 01000010 11010111 01001011 10101011 11110110
  Chars:   ..LB.K..
  Time:    Thu May  4 09:56:56.667 3623 (UTC + 8:00)
  Float:   low -2.23939e+014 high 1.31985e-033
  Double:  5.29119e-266

0:072> .time
Debug session time: Thu May  4 09:58:39.000 2023 (UTC + 8:00)
System Uptime: 40 days 10:15:42.713
Process Uptime: 0 days 16:55:48.000
  Kernel time: 0 days 0:01:54.000
  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 在這小小的花園裡，挖呀挖呀挖！ 讓朋友對外有資料層面的說服力。

圖片名稱