記一次 .NET 某無語的電商采集系統(tǒng) CPU爆高分析

一：背景

1. 講故事

前段時間有位朋友微信上找到我，說他們docker中的采集程序出現(xiàn)了CPU爆高的情況，讓我?guī)兔聪略趺椿厥拢约鹤チ藗€dump，感覺這位朋友動手能力還是比較強的，可能調試這塊知識不熟悉，不知道如何分析，既然找到我，那就給他分析下吧。

二：CPU爆高分析

1. 為什么會爆高

在動手觀察CPU是否爆高之前，我一般都會先看一下這個cpu的能力怎么樣，在 windows 上相信大家都知道用 !cpuid 輕松觀察，但在 linux 上相對來說麻煩點，但也有兩種方式。

觀察 heap 個數(shù)

由于是網(wǎng)站類型，默認是 servergc，而servergc有一個特性就是堆個數(shù)與邏輯核保持一致，所以觀察heap的個數(shù)可以間接得到，使用 !eeversion 或 !eeheap -gc 命令，輸出如下：


0:000> !eeversion
4.700.20.51601 (3.x runtime)
4.700.20.51601 @Commit: d989459717cbce34262060c4b8b949185033e379
Server mode with 2 gc heaps
SOS Version: 8.0.10.10501 retail build

0:000> !eeheap -gc

========================================
Number of GC Heaps: 2
----------------------------------------
Heap 0 (0000000000cd4aa0)
generation 0 starts at 7f509cc107d8
generation 1 starts at 7f509cb84f80
generation 2 starts at 7f509bfff000
ephemeral segment allocation context: none
Small object heap
         segment            begin        allocated        committed allocated size       committed size      
    7f509bffe000     7f509bfff000     7f509ccccfa8     7f509cec0000 0xccdfa8 (13426600)  0xec2000 (15474688) 
Large object heap starts at 7f529bfff000
         segment            begin        allocated        committed allocated size       committed size      
    7f529bffe000     7f529bfff000     7f529c30c268     7f529c30d000 0x30d268 (3199592)   0x30f000 (3207168)  
------------------------------
Heap 1 (0000000000d30950)
generation 0 starts at 7f519cf7fcb0
generation 1 starts at 7f519cf10788
generation 2 starts at 7f519bfff000
ephemeral segment allocation context: none
Small object heap
         segment            begin        allocated        committed allocated size       committed size      
    7f519bffe000     7f519bfff000     7f519d018728     7f519d1fe000 0x1019728 (16881448) 0x1200000 (18874368)
Large object heap starts at 7f52abfff000
         segment            begin        allocated        committed allocated size       committed size      
    7f52abffe000     7f52abfff000     7f52ac45bb10     7f52ac45c000 0x45cb10 (4573968)   0x45e000 (4579328)  
------------------------------
GC Allocated Heap Size:    Size: 0x2451448 (38081608) bytes.
GC Committed Heap Size:    Size: 0x282f000 (42135552) bytes.

從卦中可以看到，當前heap=2，尼瑪。。。這 docker 只有兩個核呀。。。。這跑啥不都得cpu爆高嘛。。。

有一些基礎的朋友可能會立即反駁，heapcount 是可以通過外部手段改的，言外之意就是你看到的可能是幻象。。。那到底是不是幻象呢？這就需要用第二種辦法了。。。

觀察 coreclr 源碼

在 coreclr 中其實有大量的全局變量，只要你讀過相應的源碼，相信很快就能找到一個全局變量 g_num_processors ，參考如下：


0:000> x libcoreclr!*process*
00007f53`45b6e928 libcoreclr!g_num_processors = 2

從卦中可以看到，確實當前邏輯核=2，這個是無法修改的。。。

2. 朋友的質疑

當知道cpucore=2的事實之后，我就不想分析了，跑一個線程就能把cpu干一半，這讓我分析個啥。。。告知完朋友之后，讓他加邏輯核來解決，但朋友提出了自己的質疑，說他的程序之前CPU不高，為什么現(xiàn)在就高了？希望我能找到問題代碼。。。

既然要找原因，那就到各個線程看看有沒有特別明顯的爆高代碼，使用 ~*e !clrstack 命令，仔細觀察了下，也沒有特別明顯的，只有一些Socket，Octopus，SqlServer 等，輸出如下：


0:000> ~*e !clrstack
...
OS Thread Id: 0x1b (19)
        Child SP               IP Call Site
00007F5069FF8CE0 00007f534654f3c7 [InlinedCallFrame: 00007f5069ff8ce0] Interop+Sys.ReceiveMessage(System.Runtime.InteropServices.SafeHandle, MessageHeader*, System.Net.Sockets.SocketFlags, Int64*)
00007F5069FF8CE0 00007f52d082d7db [InlinedCallFrame: 00007f5069ff8ce0] Interop+Sys.ReceiveMessage(System.Runtime.InteropServices.SafeHandle, MessageHeader*, System.Net.Sockets.SocketFlags, Int64*)
00007F5069FF8CD0 00007f52d082d7db ILStubClass.IL_STUB_PInvoke(System.Runtime.InteropServices.SafeHandle, MessageHeader*, System.Net.Sockets.SocketFlags, Int64*)
...
00007F5069FF9D80 00007f52d19d736d Octopus.xxxx.TaskService.GetTemplateTask(System.String)
...
OS Thread Id: 0x23 (27)
        Child SP               IP Call Site
00007F50617F96B0 00007f534614f7ef [InlinedCallFrame: 00007f50617f96b0] Interop+Sys.WaitForSocketEvents(IntPtr, SocketEvent*, Int32*)
00007F50617F96B0 00007f52d082a7bb [InlinedCallFrame: 00007f50617f96b0] Interop+Sys.WaitForSocketEvents(IntPtr, SocketEvent*, Int32*)
00007F50617F96A0 00007f52d082a7bb ILStubClass.IL_STUB_PInvoke(IntPtr, SocketEvent*, Int32*)
00007F50617F9730 00007f52d0add25c System.Net.Sockets.SocketAsyncEngine.EventLoop() [/_/src/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEngine.Unix.cs @ 311]
00007F50617F9780 00007f52d0add219 System.Net.Sockets.SocketAsyncEngine+c.<.ctor>b__23_0(System.Object) [/_/src/System.Net.Sockets/src/System/Net/Sockets/SocketAsyncEngine.Unix.cs @ 285]
00007F50617F9790 00007f52cbd74d83 System.Threading.Tasks.Task.InnerInvoke() [/_/src/System.Private.CoreLib/shared/System/Threading/Tasks/Task.cs @ 2445]
00007F50617F97B0 00007f52cbd74b91 System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef, System.Threading.Thread) [/_/src/System.Private.CoreLib/shared/System/Threading/Tasks/Task.cs @ 2378]
00007F50617F9830 00007f52cbd749e8 System.Threading.Tasks.Task.ExecuteEntryUnsafe(System.Threading.Thread) [/_/src/System.Private.CoreLib/shared/System/Threading/Tasks/Task.cs @ 2321]
00007F50617F9850 00007f52cbd8196b System.Threading.Tasks.ThreadPoolTaskScheduler+c.<.cctor>b__10_0(System.Object) [/_/src/System.Private.CoreLib/shared/System/Threading/Tasks/ThreadPoolTaskScheduler.cs @ 36]
00007F50617F9860 00007f52cbd5593a System.Threading.ThreadHelper.ThreadStart(System.Object) [/_/src/System.Private.CoreLib/src/System/Threading/Thread.CoreCLR.cs @ 81]
00007F50617F9BD0 00007f534565d49f [GCFrame: 00007f50617f9bd0] 
00007F50617F9CA0 00007f534565d49f [DebuggerU2MCatchHandlerFrame: 00007f50617f9ca0] 
...

OS Thread Id: 0x17 (15)
        Child SP               IP Call Site
00007F506BFFE5F0 00007f534654b35b [InlinedCallFrame: 00007f506bffe5f0] Confluent.Kafka.Impl.NativeMethods.NativeMethods_Debian9.rd_kafka_poll(IntPtr, IntPtr)
00007F506BFFE5F0 00007f52d080fc73 [InlinedCallFrame: 00007f506bffe5f0] Confluent.Kafka.Impl.NativeMethods.NativeMethods_Debian9.rd_kafka_poll(IntPtr, IntPtr)
00007F506BFFE5E0 00007f52d080fc73 ILStubClass.IL_STUB_PInvoke(IntPtr, IntPtr)
00007F506BFFE670 00007f52d080f964 Confluent.Kafka.Producer`2+c__DisplayClass24_0[[System.__Canon, System.Private.CoreLib],[System.__Canon, System.Private.CoreLib]].b__0()

只有兩個邏輯核，卻跑了若干個線程，cpu高也能說的過去，看起來不像是bug代碼導致的，而是正常的新陳代謝，總不能讓馬兒跑，又不讓馬兒吃草吧。。。為了進一步確認，讓朋友上一下 dotnet-trace。

3. dotnet-trace 跟蹤

在Windows之外的系統(tǒng)里，可以使用 dotnet-trace 跟蹤，雖然有點弱雞，但也沒有辦法，讓朋友在 cpu 高的時候開啟，很快 trace.nettrace 也抓到了，抓到之后，我們拖到 DotTrace 中看一下，因為他有非常強的可視化視圖，這是我比較喜歡他的一個重要原因，也是眾多 jetbrains 產(chǎn)品中的唯一一個，截圖如下：