記一次 .NET 某醫院門診軟體 卡死分析
2023-05-15 12:02:40
一：背景
1. 講故事
前幾天有位朋友找到我，說他們的軟體在客戶那邊卡死了，讓我幫忙看下是怎麼回事？我就讓朋友在程式卡死的時候通過 工作管理員 抓一個 dump 下來，雖然預設抓的是 wow64 ，不過用 soswow64.dll 轉還是可以的，參考命令如下：
.load C:\soft\soswow64\soswow64.dll
!wow64exts.sw
接下來就可以分析了哈。
二：WinDbg 分析
1. 為什麼會卡死
首先用 !t 簡單看一下主執行緒的 COM Apartment 模式，如果是 STA 那就是表單程式，比如 WPF，WinForm 之類的，輸出如下：
0:000:x86> !t
ThreadCount: 39
UnstartedThread: 0
BackgroundThread: 12
PendingThread: 0
DeadThread: 26
Hosted Runtime: no
Lock
ID OSID ThreadOBJ State GC Mode GC Alloc Context Domain Count Apt Exception
0 1 1928 01aee0b0 2026020 Preemptive 041D496C:00000000 01ae88a8 2 STA
...
既然是表單程式那就看主執行緒吧，使用 ~0s;!clrstack 命令。
0:000:x86> !clrstack
OS Thread Id: 0x1928 (0)
Child SP IP Call Site
0177dff8 0167e1f8 [HelperMethodFrame_1OBJ: 0177dff8] System.Threading.SynchronizationContext.WaitHelper(IntPtr[], Boolean, Int32)
0177e29c 6a6fc693 System.Windows.Threading.DispatcherSynchronizationContext.Wait(IntPtr[], Boolean, Int32)
0177e2b0 71e36d54 System.Threading.SynchronizationContext.InvokeWaitMethodHelper(System.Threading.SynchronizationContext, IntPtr[], Boolean, Int32) [f:\dd\ndp\clr\src\BCL\system\threading\synchronizationcontext.cs @ 349]
0177e4d8 73220076 [GCFrame: 0177e4d8]
0177e5f8 73220076 [GCFrame: 0177e5f8]
0177e6d8 73220076 [GCFrame: 0177e6d8]
0177e6f4 73220076 [HelperMethodFrame_1OBJ: 0177e6f4] System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef)
0177e770 18078b93 System.Speech.Internal.Synthesis.AudioDeviceOut.Abort()
0177e79c 17270698 System.Speech.Internal.Synthesis.VoiceSynthesis.Abort()
0177e7e8 065ec76b System.Speech.Synthesis.SpeechSynthesizer.SpeakAsyncCancelAll()
0177e7f0 065ec728 xxx.xxx.Speek(System.String)
...
從卦中看是一個 語音模組，還有 Speek 功能，挺有意思。。。 還 Speek 啥呢？可以用 !mdso 看一下。
0:000:x86> !mdso
Thread 0:
Location Object Type
------------------------------------------------------------
0177e060 04176eb8 System.IntPtr[]
...
0177e7f8 03be9504 System.String "請先登入驗證身份"
哈哈，上面只是花絮，繼續看執行緒棧會發現程式碼卡在 Monitor.ReliableEnter 上，也就是等待 lock 鎖，接下來用 kb 把 鎖物件提取出來，即 clr!JITutil_MonReliableEnter 方法的第一個引數 03be11b4，輸出如下：
0:000:x86> kb
...
17 0177e768 18078b93 03be11b4 00000000 00000000 clr!JITutil_MonReliableEnter+0xb5
18 0177e794 17270698 0177e7bc 73252799 00000000 0x18078b93
19 0177e7e0 065ec76b 0177e808 065ec728 00000000 0x17270698
1a 0177e7e8 065ec728 00000000 03a0b318 03be9504 0x65ec76b
1b 0177e808 1727e09f 00000000 03be0920 04158b98 0x65ec728
1c 0177e824 69181324 04175c04 041199c0 00000001 0x1727e09f
...
0:000:x86> !do 03be11b4
Name: System.Object
MethodTable: 71f200f4
EEClass: 71a715b0
Size: 12(0xc) bytes
File: C:\Windows\Microsoft.Net\assembly\GAC_32\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
Object
Fields:
None
有了這個物件就可以用 !syncblk 命令觀察同步塊表，到底是哪個執行緒在持有不釋放？
0:000:x86> !syncblk
Index SyncBlock MonitorHeld Recursion Owning Thread Info SyncBlock Owner
96 11ac3ee0 3 1 11af0f28 35d4 13 03be11b4 System.Object
-----------------------------
Total 931
CCW 39
RCW 19
ComClassFactory 2
Free 802
0:000:x86> ~13s;!clrstack
ntdll_76fc0000!NtWaitForSingleObject+0xc:
7703159c c20c00 ret 0Ch
OS Thread Id: 0x35d4 (13)
Child SP IP Call Site
17f8f23c 0000002b [InlinedCallFrame: 17f8f23c]
17f8f238 1adf3269 DomainBoundILStubClass.IL_STUB_PInvoke(IntPtr)
17f8f23c 1adf2e82 [InlinedCallFrame: 17f8f23c] System.Speech.Internal.Synthesis.SafeNativeMethods.waveOutClose(IntPtr)
17f8f26c 1adf2e82 System.Speech.Internal.Synthesis.AudioDeviceOut.End()
17f8f298 187a5cd6 System.Speech.Internal.Synthesis.VoiceSynthesis.SpeakText(System.Speech.Internal.Synthesis.SpeakInfo, System.Speech.Synthesis.Prompt, System.Collections.Generic.List`1<System.Speech.Internal.Synthesis.LexiconEntry>)
17f8f304 17271669 System.Speech.Internal.Synthesis.VoiceSynthesis.ThreadProc()
17f8f3b8 71e3710d System.Threading.ThreadHelper.ThreadStart_Context(System.Object) [f:\dd\ndp\clr\src\BCL\system\threading\thread.cs @ 74]
17f8f3c4 71e640c5 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean) [f:\dd\ndp\clr\src\BCL\system\threading\executioncontext.cs @ 954]
17f8f430 71e63fd6 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean) [f:\dd\ndp\clr\src\BCL\system\threading\executioncontext.cs @ 902]
17f8f444 71e63f91 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) [f:\dd\ndp\clr\src\BCL\system\threading\executioncontext.cs @ 891]
17f8f45c 71e37068 System.Threading.ThreadHelper.ThreadStart() [f:\dd\ndp\clr\src\BCL\system\threading\thread.cs @ 111]
17f8f5a0 73220076 [GCFrame: 17f8f5a0]
17f8f784 73220076 [DebuggerU2MCatchHandlerFrame: 17f8f784]
0:013:x86> !t
...
13 14 35d4 11af0f28 2b220 Preemptive 00000000:00000000 01ae88a8 2 MTA
...
從卦中資訊看：13號執行緒持有了 lock 鎖，並且它非執行緒池執行緒，而是通過 new Thread 出來的，從執行緒棧看都是sdk函數，綜合這些資訊，應該是 VoiceSynthesis 建立出來的後臺執行緒，下面的圖也可以佐證。
接下來繼續看，從執行緒棧頂上可以觀察到最後卡在了 System.Speech.Internal.Synthesis.SafeNativeMethods.waveOutClose 方法處，逆向之後的程式碼如下：
// System.Speech.Internal.Synthesis.AudioDeviceOut
internal override void End()
{
if (!_deviceOpen)
{
throw new InvalidOperationException();
}
lock (_noWriteOutLock)
{
_deviceOpen = false;
CheckForAbort();
if (_queueIn.Count != 0)
{
SafeNativeMethods.waveOutReset(_hwo);
}
MMSYSERR mMSYSERR = SafeNativeMethods.waveOutClose(_hwo);
}
}
由於這是 Windows 的 VoiceSynthesis 模組封裝底層函數，經過千錘百煉，理論上出問題的概率會非常小，除非上層有不合理的呼叫，這種概率會大一些。
2. 是上層不合理的呼叫嗎
這一塊我也沒玩過，網上搜一下 waveOutReset , waveOutClose ，看下有沒有同病相憐的人，結果網上一搜一堆，比如下面這樣：
不管怎麼說，這一塊如果處理不好容易出現死鎖和卡死的情況，那是不是正如圖中所說 waveOutReset 和 waveOutClose 沒有匹配造成的呢？
這就取決於程式碼中的 _queueIn 集合，可以觀察這兩個函數的組合程式碼提取出這個變數。
0:013:x86> !U /d 1adf2e82
Normal JIT generated code
System.Speech.Internal.Synthesis.AudioDeviceOut.End()
...
1adf2e30 8bf1 mov esi,ecx
...
1adf2e69 8b4608 mov eax,dword ptr [esi+8]
1adf2e6c 83780c00 cmp dword ptr [eax+0Ch],0
1adf2e70 7408 je 1adf2e7a
...
0:013:x86> !U /d 187a5cd6
Normal JIT generated code
System.Speech.Internal.Synthesis.VoiceSynthesis.SpeakText(System.Speech.Internal.Synthesis.SpeakInfo, System.Speech.Synthesis.Prompt, System.Collections.Generic.List`1<System.Speech.Internal.Synthesis.LexiconEntry>)
...
187a5cc8 8b45d0 mov eax,dword ptr [ebp-30h]
187a5ccb 8b486c mov ecx,dword ptr [eax+6Ch]
187a5cd3 ff5014 call dword ptr [eax+14h]
>>> 187a5cd6 58 pop eax
...
0:013:x86> kb 10
# ChildEBP RetAddr Args to Child
...
08 17f8f264 1adf2e82 03be11b4 00000001 00000000 0x1adf3269
09 17f8f290 187a5cd6 187a5e16 03be0d24 043f3520 0x1adf2e82
0a 17f8f2f4 17271669 040efa14 040ef9a4 732515d8 0x187a5cd6
0b 17f8f3b0 71e3710d 03ff3e98 17f8f420 71e640c5 0x17271669
...
仔細觀察上面的組合程式碼：eax 來自於 esi，esi 來自於 ecx，ecx 最終來自於父函數中的 ebp-30h 的位置，串聯起來的命令就是 !do poi(poi(poi(17f8f2f4-30)+6c)+0x8) ，接下來我們 do 一下。
0:000:x86> !do poi(poi(poi(17f8f2f4-30)+6c)+0x8)
Name: System.Collections.Generic.List`1[[System.Speech.Internal.Synthesis.AudioDeviceOut+InItem, System.Speech]]
MethodTable: 16cf20ec
EEClass: 71af6f8c
Size: 24(0x18) bytes
File: C:\Windows\Microsoft.Net\assembly\GAC_32\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
Fields:
MT Field Offset Type VT Attr Value Name
71f2f320 4001891 4 System.__Canon[] 0 instance 03c74538 _items
71f21bb4 4001892 c System.Int32 1 instance 0 _size
71f21bb4 4001893 10 System.Int32 1 instance 1900 _version
71f200f4 4001894 8 System.Object 0 instance 00000000 _syncRoot
71f2f320 4001895 4 System.__Canon[] 0 static <no information>
可以看到此時的 _size=0 ，有可能就是因為上層不合理呼叫導致這裡的 _queueIn 意外為 0 ，最終引發的卡死現象。
3. 真相大白
一時之間也找不到上層哪裡有不合理的呼叫，接下來的思路還是自己研讀主執行緒和13號執行緒的呼叫棧，最後發現一個可疑的現象，截圖如下：
通過仔細研讀底層程式碼，Speek 會將訊息丟到底層的queue佇列中，後臺執行緒會提取處理，這裡的 SpeakAsyncCancelAll 是完全沒必要的。
有了這個訊息，就讓朋友把這個函數去掉觀察下試試，據朋友反饋說沒有問題了。
三：總結
這個案例中去掉了意外的 speech.SpeakAsyncCancelAll(); 語句就搞定了，內部深層邏輯也沒有再探究了，大概率就是意外的 _queueIn 為 0，讓 waveOutReset 和 waveOutClose 方法沒有匹配出現，造成了卡死現象。
