阿里短信回執.net sdk的bug致使生產服務cpu 100%排查

一：背景

1. 講故事

去年阿里聚石塔上的全部isv短信通道所有對接阿里通訊，咱們就作了對接改造，使用阿里提供的.net sdk。

網址：https://help.aliyun.com/document_detail/114480.html

同事當時使用的是ons-.net v1.1.3版本，程序上線後若干天就會有一次程序崩潰現象，當時也沒特別在乎，覺得是本身代碼或者環境出了什麼問題，索性就加了一個檢測程序，若是檢測到sdk程序退出就自動重啓，就這樣先糊弄着，直到有一天服務器告警，那個程序CPU竟然飆到100%，服務器但是16核128G的哦。。。

二：分析問題

1. 抓dump文件

狀況比較緊急，立刻給程序發送Ctrl+C命令讓程序退出，結果又退出不了，奇葩。。。爲了分析問題抓了一個dump下來，而後強制kill掉程序。

2. 查看線程池以及各個線程正在作什麼？

0:000> !tp
CPU utilization: 100%
Worker Thread: Total: 0 Running: 0 Idle: 0 MaxLimit: 32767 MinLimit: 16
Work Request in Queue: 0
--------------------------------------
Number of Timers: 1
--------------------------------------
Completion Port Thread:Total: 1 Free: 1 MaxFree: 32 CurrentLimit: 1 MaxLimit: 1000 MinLimit: 16

從 CPU utilization: 100% 上看，果真cpu100%了，發現 Worker Thread 沒有Running 線程，多是由於執行了Ctrl+C都銷燬了，接下來用 ~*e !clrstack 把全部的託管線程棧打出來。

0:000> ~*e !clrstack
OS Thread Id: 0x1818 (0)
Unable to walk the managed stack. The current thread is likely not a 
managed thread. You can run !threads to get a list of managed threads in
the process
Failed to start stack walk: 80070057

從輸出結果看，沒有任何託管線程，惟一的那個線程0還不是還託管線程，而後改爲 ~*e !dumpstack把非託管線程棧找出來。

0:000> ~*e !dumpstack
OS Thread Id: 0x1818 (0)
Current frame: ntdll!ZwRemoveIoCompletion+0x14
Child-SP         RetAddr          Caller, Callee
000000637323ef40 00007ff8327bac2f KERNELBASE!GetQueuedCompletionStatus+0x3f, calling ntdll!ZwRemoveIoCompletion
000000637323efa0 00007ff81b9c8a00 ONSClient4CPP!metaq_juce::URL::launchInDefaultBrowser+0x273d0, calling kernel32!GetQueuedCompletionStatus
000000637323f090 00007ff81ba3eb0a ONSClient4CPP!ons::Message::getMsgBody+0x5a8a, calling ONSClient4CPP!metaq_juce::URL::launchInDefaultBrowser+0x1f100
000000637323f140 00007ff81ba3f084 ONSClient4CPP!ons::Message::getMsgBody+0x6004, calling ONSClient4CPP!ons::Message::getMsgBody+0x5800
000000637323f280 00007ff81ba233b4 ONSClient4CPP!ons::ONSFactoryProperty::setSendMsgTimeout+0xa6b4, calling ONSClient4CPP!ons::ONSFactoryProperty::setSendMsgTimeout+0xa5d0
000000637323f2b0 00007ff81ba11b43 ONSClient4CPP!ons::ONSFactoryAPI::~ONSFactoryAPI+0x153
000000637323f310 00007ff81ba12d64 ONSClient4CPP!ons::SendResultONS::operator=+0xc44, calling ONSClient4CPP!ons::ONSFactoryAPI::~ONSFactoryAPI+0x10
000000637323f460 00007ff81ba83eb4 ONSClient4CPP!ons::Message::getStoreTimestamp+0xf484, calling ONSClient4CPP!ons::Message::getStoreTimestamp+0xf1c4
000000637323f630 00007ff8356f7d94 ntdll!RtlExitUserProcess+0xb4, calling ntdll!LdrShutdownProcess
000000637323f690 00007ff832777c23 KERNELBASE!CtrlRoutine+0xa3
000000637323f780 00007ff834df8364 kernel32!BaseThreadInitThunk+0x14, calling kernel32!WriteConsoleOutputW+0x530

從非託管調用棧來看，其中KERNELBASE!CtrlRoutine 代表主線程接受到了Ctrl+C命令， 從棧頂發現貌似不能退出的緣由是主線程被 ONSClient4CPP 接管，並且這個C++正在作遠程鏈接再等待網絡IO返回，但這種會把16核cpu打滿應該不太可能，這個問題貌似到這裏就卡住了。

三： 重啓程序發現問題依舊

1. 抓dump文件

很開心的是程序從新啓動後，過了兩分鐘CPU又在飆升，此次學乖了，等CPU到了60，70%的時候抓dump文件。

2. 繼續排查

0:000> .time
Debug session time: Fri Apr 17 17:36:50.000 2020 (UTC + 8:00)
System Uptime: 355 days 5:33:48.092
Process Uptime: 0 days 0:02:11.000
  Kernel time: 0 days 0:03:31.000
  User time: 0 days 0:13:22.000


0:000> !tp
CPU utilization: 59%
Worker Thread: Total: 3 Running: 0 Idle: 3 MaxLimit: 32767 MinLimit: 16
Work Request in Queue: 0
--------------------------------------
Number of Timers: 1
--------------------------------------
Completion Port Thread:Total: 2 Free: 2 MaxFree: 32 CurrentLimit: 2 MaxLimit: 1000 MinLimit: 16

從上面代碼能夠看到，進程啓動了2分11秒，此次cpu利用率是59%，抓的有點早，不過不要緊，先看一下Threads狀況。

0:000> !threads
ThreadCount:      25
UnstartedThread:  0
BackgroundThread: 8
PendingThread:    0
DeadThread:       16
Hosted Runtime:   no
                                                                                                        Lock  
       ID OSID ThreadOBJ           State GC Mode     GC Alloc Context                  Domain           Count Apt Exception
   0    1  cdc 0000022bb9f53220    2a020 Preemptive  0000022BBBFACCE8:0000022BBBFADFD0 0000022bb9f27dc0 1     MTA 
   2    2  3dc 0000022bb9f7f9f0    2b220 Preemptive  0000000000000000:0000000000000000 0000022bb9f27dc0 0     MTA (Finalizer) 
   3    4 296c 0000022bb9fe97b0  102a220 Preemptive  0000000000000000:0000000000000000 0000022bb9f27dc0 0     MTA (Threadpool Worker) 
XXXX    5    0 0000022bb9ffc5a0  1039820 Preemptive  0000000000000000:0000000000000000 0000022bb9f27dc0 0     Ukn (Threadpool Worker) 
XXXX    6    0 0000022bd43938c0  1039820 Preemptive  0000000000000000:0000000000000000 0000022bb9f27dc0 0     Ukn (Threadpool Worker) 
.............................................................................
 163   24 29e8 0000022bd4898650  1029220 Preemptive  0000022BBC102108:0000022BBC103FD0 0000022bb9f27dc0 0     MTA (Threadpool Worker) 
 164   25 2984 0000022bd489d470  1029220 Preemptive  0000022BBC0EA2D0:0000022BBC0EBFD0 0000022bb9f27dc0 0     MTA (Threadpool Worker)

好傢伙，才2分11秒，託管線程ThreadCount: 25就死了DeadThread: 16個，並且從threads列表中看，windbg給的最大編號是164，說明當前有 (164+1) - 25 =142 個非託管線程，應該就是阿里的ONSClient4CPP開啓的，爲何開啓這麼多線程，這就是一個很值得關注的問題了，接下來仍是用 ~*e !dumpstack 把全部線程的託管和非託管線程棧打出來，因爲信息太多，我就截幾張圖。

---

我的猜想，純技術討論：

---

圖1：

從堆棧上看，有105個線程卡在 ntdll!ZwRemoveIoCompletion+0x14 這裏，並且從 ONSClient4CPP!metaq_juce::URL::launchInDefaultBrowser+0x23072 中看，貌似阿里開了一個瀏覽器內核，用內核來發送數據，估計這裏併發閾值開的還挺大的，諮詢了下同事是前面有一家大客戶發了不少的短信，估計是大量的回持積壓，這個C# sdk進行了瘋狂讀取，這個跟CPU暴漲應該有脫不了的關係。

圖2：

從檢索上看有28個線程貌似正在臨界區等待鎖，CPU高的一個經典案例就是當不少線程在臨界區等待的時候，當某一個正在臨界區中的線程離開後，這28個線程的調度競搶也是CPU高的一個緣由。

我的水平有限，進一步挖非託管堆目前還沒這個技術(┬＿┬) 。。。

四： 解決方案

這種SDK的問題還能有什麼解決方案，能想到的就是去官網找下可有最新版：

能夠看到最新版的 ons-.net v1.1.4 中提到的優化點：優化消息拉取流程，避免特殊狀況下拉取異常形成的消息堆積。

果真用了最新版的sdk就能夠了，🐮👃。

---

如您有更多問題與我互動，掃描下方進來吧~

---