## 一：背景 ### 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. 檢視執行緒池以及各個執行緒正在做什麼？ ``` C# 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` 把所有的託管執行緒棧打出來。 ``` C# 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`把非託管執行緒棧找出來。 ``` C# 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. 繼續排查 ``` C# 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`情況。 ``` C# 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就可以了，