Sysmon占用CPU及內存過高問題分析與解決方法

今天就跟大家聊聊有關Sysmon占用CPU及內存過高問題分析與解決方法，可能很多人都不太了解，為了讓大家更加了解，小編給大家總結了以下內容，希望大家根據這篇文章可以有所收獲。

一、背景

最近有個項目用到了sysinternals出品的監控工具：sysmon.exe。但是有反饋，sysmon.exe進程（下文為方便描述簡稱為sysmon）在某一特定條件下，持續占用cpu，一般為會跑滿cpu的一個邏輯核。例如，如果cpu為雙核4線程，則sysmon的占用在25%。且sysmon占用的內存持續升高。

圖 1. sysmon的高cpu、內存占用

二、問題定位與分析

問題初步定位

使用ProcessExplorer觀察sysmon進程各個線程的cpu使用情況，發現各個線程的cpu占用率并不高。但是發現有大量的新線程被創建，同時又有大量的舊線程被銷毀。可見，cpu時間片被主要用于線程的創建、銷毀操作了。

圖 2. 紅色為線程銷毀、綠色為線程創建 

同時觀察sysmon的句柄使用情況，發現句柄數量異常的高，竟然在非常短的時間內達到了萬的量級。

圖 3. 句柄數量異常

所以接下來的分析重點將圍繞線程的大量創建和銷毀以及句柄的異常創建展開。

調試器中定位問題

I. 定位線程大量創建銷毀的問題

由圖2可知，創建的線程都是以sysmon.exe+0x494a8這個地址開始的。順著這個線索摸過去，發現sysmon+0x495aa這個堆棧返回地址，范圍落在sysmon.exe+0x494a8這個函數的范圍內。順著sysmon+0x495aa這個棧回溯線索往回找，最終確定sysmon+0x1820e為出問題的函數,下圖為sysmon各個子線程的棧回溯：

圖 4. 定位到出問題的函數    

分析進行到這里先暫時告一段落，稍后再驗證分析的是否正確。接下來，跟進第二個問題：內存占用過高。

II. 定位內存占用過高問題

由圖3可知，sysmon在段時間內創建了大量的句柄，在調試器中看下這些句柄的使用情況：

圖 5. 句柄全局統計

由上圖可以看到，短短幾分鐘之內，句柄數目由圖3的4.5萬多個增加到現在的72942個，其中Event類型的句柄占了72878個，比例高達99%，而且這些event都需要人工重置狀態。這隱含著一個信息，在程序沒有人工重置這些event的狀態前，event不會被釋放。短時間內創建如此量級的事件且不釋放，時間久了，內存占用自然就上去了。

在調試器中確認問題

I. 內存占用過高問題的確認

通過上一節的分析，我們初步定位了cpu以及內存占用過高的原因。接下來我們來確定一下，是否是因為這個原因導致的。趁著各位剛看完內存占用過高的問題，我們先從這個問題入手。

熟悉windows編程的人可以知道，創建event一般會調用CreateEvent這個函數。那么我們在此函數上下如下斷點：

解釋一下這個斷點的意思：首先斷在kernel32.dll中的CreateEventW函數調用的開始，然后打印一下堆棧調用，最后恢復程序的執行。

OK，下面是執行結果的一部分：

圖 6. 在創建Event時獲取棧回溯調用

上圖是大概執行了5秒鐘左右的樣子，從右邊下拉條來看輸出大概有幾千條，也就是5秒鐘內創建了幾千個Event，這和我們上面觀察到的句柄暴增現象項符。往上翻一下每次的棧回溯輸出，發現都是sysmon+0x181b7這個附近出發了CreateEventW的調用。同時這里先埋個包袱：注意OpenTraceW函數。

這里同樣還有另外一個需要注意的地方，就是圖6中的最后一個sysmon模塊的函數調用返回地址：sysmon+0x181b7。結合圖4中我們定位的，離導致新線程不停被創建的地址sysmon+0x1820e很近。至于這兩個地址的因果關系，詳見下文分析。

II. 線程大量創建銷毀的問題的確認

剛才提到 sysmon+0x181b7與sysmon+0x1820e兩個地址很近，下圖可以讓各位在直觀上了解一下兩個地址究竟有多近：

圖 7. sysmon+181b7與sysmon+1820e

所以，根據現在掌握的證據來看，故事很有可能是這樣的：

1. 大量創建線程

2. 新創建的線程中又大量創建了Event

3. 創建的線程退出了，但是由于Event需要Manual Reset，所以Event并沒有被釋放

天下沒有免費的午餐，這么大量的Event是需要內存存放的。所以，大量創建線程導致cpu使用變高，大量創建未釋放的Event導致內存使用變高。

看到這里你可能會說，上面都是你的猜測，有什么證據支持么？下面我們在調試器中驗證我們上面的猜測。在正式開始之前，我想先闡述一下我的思路：上面的分析結論是，新創建的線程導致新創建了Event；所以，如果我們下兩個斷點，第一個斷點在sysmon+0x1820e處，第二個斷點在系統的CreateEventW函數上；那么，這兩個斷點應該是交替命中；由于兩個斷點一個是位于sysmon模塊的線程函數地處，另外一個則為與系統的kernel32.dll模塊地址，所以兩個斷點理論上并沒有必然聯系，如果現象真的是兩個斷點交替命中，則可以驗證我們上文的猜測。

下面是實際操作，首先是兩個斷點：

圖    8. 兩個斷點

解釋一下，首先是每行最開始的數值是斷點編號，0代表0號斷點，1代表1號斷點；e代表兩個斷點都是激活（enable）狀態；然后是后面的kernel32!CreateEventW和sysmon+0x1820e，代表著該斷點的地址（具體見上文分析）；最后雙引號里.echo開頭的意義為，一旦命中該地址的斷點，打印一下當前斷點的編號與堆棧調用關系，最后恢復執行。下面是命中的情況：

圖 9. 斷點交替命中

可見現象與我們設想一致，印證了我們猜測的正確性。可能，有較真的讀者還是會說，你現在說的這些都還是間接證據。那么，接下來我們就和這個問題剛一下正面，用代碼說明問題。

出現此問題的根本證據

上文中的兩個地址（sysmon+181b7與sysmon+1820e）都位于函數sysmon+0x180E0中。直接給出此函數的偽代碼：

圖 10. 導致cpu過高線程的入口函數

這里說一下關鍵邏輯，注意圖10中的第44行處的函數調用sub_140018360,以及本函數的地址sub_1400180e0。本代碼片段的意義是，在某個全局信號的作用下，有可能會調用到sub_140018360這個函數，同時給這個函數傳一個參數為1。

接下來看一下sub_140018360函數做了什么，為了方便說明問題，偽代碼做了部分折疊處理： 

圖 11. 導致遞歸調用的地方

注意69行的線程創建函數，也就是說，在sub_140018360函數的參數為1的情況下，不出錯，會走到69行的線程創建，線程的入口函數是sub_1400180e0。眼熟么？不眼熟的請看下圖10。也就是說，sub_1400180e0最后會調用sub_140018360函數，而sub_140018360函數內部創建了一個線程，創建的這個線程又調用回了sub_1400180e0函數，而由圖6的分析可知，正是由于sub_1400180e0里面的OpenTraceW函數導致創建了大量的Event，從而使內存飆升。這是一個類似遞歸調用的邏輯，如果一致走下去，是不會有盡頭的。

分析到這里，就很清楚了。為了拿到某種Trace的結果（上文中提到的包袱，OpenTraceW函數），sysmon用了一個類似遞歸的邏輯，反復重試嘗試獲取拿到結果。正是由于：

1. 遞歸調用創建線程，導致cpu使用率飆升

2. 上面創建的線程通過OpenTraceW創建了大量Event，導致內存飆升

至此，sysmon占用高cpu和高內存的直接原因已經找到。

三、什么原因導致的此問題的產生

在調試過程中，發現如下幾個現象：

1. sysmon會重啟一次，且重啟后的sysmon才會有高cpu和內存占用

2. sysmon重啟前TsService.exe會拉起幾個進程，但是拉起的進程結束的很快

看到這里，可能各位有個疑問，TsService.exe是什么東西？答案是，此進程為QQ瀏覽器的后臺服務進程。證據如下（此可執行文件有正常的騰訊簽名）：

圖 12. TsService.exe為QQ瀏覽器的服務進程

然后，我跟進了一下TsService.exe啟動的那幾個進程是什么：

圖 13. TsService.exe啟動的子進程

順帶一提，圖13中的子進程，第一行沒截全的地方是：set-default-browser --slient  ;-）。嗯，接下來才是我們需要關注的點，幾個xperf子進程的命令。

寫到這里，插個題外話，在解決這個問題查資料的過程中，查到過這么一篇資料：《QQ瀏覽器性能提升之路-windows性能分析工具篇》。這篇文章貼心的給出了圖13中xperf命令的詳細解釋：

圖 14. 騰訊方面對xper參數的解釋

以及踩過的坑：

圖 15. 文中提到的啟動失敗的情況

文中提到了ProcessMonitor和ProcessExplorer會導致xperf失敗，需要先關閉再啟動。經過我的測試，sysmon也是會導致xper.exe拋出上圖中相同的錯誤。

再插一個題外話，xperf為微軟官方提供的性能信息收集工具，借助此工具可以分系windows系統上程序的許多性能問題。

還記得本節剛開始提到的兩個現象么——sysmon重啟后會出現高占用現象。難道和騰訊瀏覽器啟動的xperf有關？

四、此問題在任意機器上的復現

為了證明上面的猜測，我做了如下實驗。

不賣關子，首先直接給出結論，通過xperf和sysmon的“協同配合”，可以在任何機器上復現sysmon高cpu和內存占用的問題。

具體步驟為：

1. 首先最好有一個全新安裝的純凈系統（可選）

2. 在系統上安裝sysmon服務，具體命令為,在管理員權限的cmd下執行: sysmon -i

3. 停止sysmon的服務（因為不停止會導致xperf命令報錯）

4. 使用xperf.exe依次執行如下命令:

5. 重新啟動sysmon服務

上述步驟執行完畢后，新啟動的sysmon服務的cpu使用率會占滿一個邏輯核。內存使用率也會慢慢的上去。

如果在sysmon的cpu使用率上去之后，再次執行

則sysmon的使用率則會降回到正常水平。

五、誰關閉了sysmon？

通過上面的分析可知，此問題出現的根本原因在于sysmon重啟后，所需要的資源（NT Kernel Logger）被占用，導致重啟后的sysmon服務無法拿到所需資源，一直在重試。那么到底是什么原因導致sysmon退出呢？

結合上文的分析，我將排查重點放在了TsService.exe服務上。通過對TsService.exe 進程的OpenServiceW函數下斷點，最終將問題定位到了PerfTool.dll這個模塊中:

圖 16. 關閉sysmon服務

六、此問題的解決方案（部分）

I. 方案一

注意，這里只是根據上文中的分析，提出幾種解決方案，不是最終的唯一解決方案。

通過圖10中的第43和44行可以知道，在調用導致“遞歸”的函數之前，還有一個if判斷，這個判斷用sub_14008da0(我已經改名為fnReadRegistryValue)的返回值，與1做邏輯與操作，只有這個操作為真的情況下才會產生“遞歸”的邏輯。接下來，我們看一下fnReadRegistryValue這個函數干了啥：

圖 17. 讀取注冊表中的配置項

可以看到，該函數的返回值為Data，而Data中的數據來自于注冊表的如下鍵值：

如果此鍵值的值，與1做與運算為0的話，即可結束“遞歸”的邏輯。也就是說，如果這個鍵值下的數值是偶數，則永遠都不會因為這兩個函數的“遞歸”調用，從而不會產生高cpu和內存占用的問題。

那么這個鍵值是干什么用的呢？從sysmon的幫助文檔可知，sysmon是一個命令行工具，是有啟動參數的，結合Options的意義，可知不同的sysmon監控啟動參數，會導致這個值的不同。后來的實驗也證實這個鍵值的確會根據sysmon的啟動參數不同而不同。

所以，一個可行的解決方案是，當cpu占用很高且內存在緩慢上升時，可以暫時將該鍵值置為0,使程序跳出“遞歸”邏輯，然后再將此值改回原來的值，以免影響其監控需求。

II. 方案二

由圖16可知, TsService.exe關閉sysmon使用的是硬編碼。而sysmon是支持安裝服務時使用其他服務名的。所以，另外一個可行的解決方案是安裝sysmon服務時，使用其他的服務名，防止被TsService.exe關閉。

正如產生本文性能問題的“遞歸”問題一樣。本來是性能排查的行為，卻最終導致了性能問題，而后需要繼續進行性能問題的排查......而此問題的出現，并不是由單一因素導致，而是多種因素共同作用的結果。由于性能測試的特殊性，并不是所有的機器都需要進行這項測試，所以初始化的那個行為：關閉sysmon，啟動xperf進行性能信息收集，并不會在每一臺機器上執行。所以，這個問題的出現，有一定的“隨機”性，并不是在每臺機器上必現。

看完上述內容，你們對Sysmon占用CPU及內存過高問題分析與解決方法有進一步的了解嗎？如果還想了解更多知識或者相關內容，請關注億速云行業資訊頻道，感謝大家的支持。