Sysmon占用CPU及內(nèi)存過(guò)高問(wèn)題分析與解決方法

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

一、背景

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

圖 1. sysmon的高cpu、內(nèi)存占用

二、問(wèn)題定位與分析

問(wèn)題初步定位

使用ProcessExplorer觀察sysmon進(jìn)程各個(gè)線程的cpu使用情況，發(fā)現(xiàn)各個(gè)線程的cpu占用率并不高。但是發(fā)現(xiàn)有大量的新線程被創(chuàng)建，同時(shí)又有大量的舊線程被銷毀?？梢?，cpu時(shí)間片被主要用于線程的創(chuàng)建、銷毀操作了。

圖 2. 紅色為線程銷毀、綠色為線程創(chuàng)建 

同時(shí)觀察sysmon的句柄使用情況，發(fā)現(xiàn)句柄數(shù)量異常的高，竟然在非常短的時(shí)間內(nèi)達(dá)到了萬(wàn)的量級(jí)。

圖 3. 句柄數(shù)量異常

所以接下來(lái)的分析重點(diǎn)將圍繞線程的大量創(chuàng)建和銷毀以及句柄的異常創(chuàng)建展開。

調(diào)試器中定位問(wèn)題

I. 定位線程大量創(chuàng)建銷毀的問(wèn)題

由圖2可知，創(chuàng)建的線程都是以sysmon.exe+0x494a8這個(gè)地址開始的。順著這個(gè)線索摸過(guò)去，發(fā)現(xiàn)sysmon+0x495aa這個(gè)堆棧返回地址，范圍落在sysmon.exe+0x494a8這個(gè)函數(shù)的范圍內(nèi)。順著sysmon+0x495aa這個(gè)棧回溯線索往回找，最終確定sysmon+0x1820e為出問(wèn)題的函數(shù),下圖為sysmon各個(gè)子線程的?；厮荩?/p>

圖 4. 定位到出問(wèn)題的函數(shù)    

分析進(jìn)行到這里先暫時(shí)告一段落，稍后再驗(yàn)證分析的是否正確。接下來(lái)，跟進(jìn)第二個(gè)問(wèn)題：內(nèi)存占用過(guò)高。

II. 定位內(nèi)存占用過(guò)高問(wèn)題

由圖3可知，sysmon在段時(shí)間內(nèi)創(chuàng)建了大量的句柄，在調(diào)試器中看下這些句柄的使用情況：

圖 5. 句柄全局統(tǒng)計(jì)

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

在調(diào)試器中確認(rèn)問(wèn)題

I. 內(nèi)存占用過(guò)高問(wèn)題的確認(rèn)

通過(guò)上一節(jié)的分析，我們初步定位了cpu以及內(nèi)存占用過(guò)高的原因。接下來(lái)我們來(lái)確定一下，是否是因?yàn)檫@個(gè)原因?qū)е碌?。趁著各位剛看完?nèi)存占用過(guò)高的問(wèn)題，我們先從這個(gè)問(wèn)題入手。

熟悉windows編程的人可以知道，創(chuàng)建event一般會(huì)調(diào)用CreateEvent這個(gè)函數(shù)。那么我們?cè)诖撕瘮?shù)上下如下斷點(diǎn)：

解釋一下這個(gè)斷點(diǎn)的意思：首先斷在kernel32.dll中的CreateEventW函數(shù)調(diào)用的開始，然后打印一下堆棧調(diào)用，最后恢復(fù)程序的執(zhí)行。

OK，下面是執(zhí)行結(jié)果的一部分：

圖 6. 在創(chuàng)建Event時(shí)獲取?；厮菡{(diào)用

上圖是大概執(zhí)行了5秒鐘左右的樣子，從右邊下拉條來(lái)看輸出大概有幾千條，也就是5秒鐘內(nèi)創(chuàng)建了幾千個(gè)Event，這和我們上面觀察到的句柄暴增現(xiàn)象項(xiàng)符。往上翻一下每次的?；厮葺敵?，發(fā)現(xiàn)都是sysmon+0x181b7這個(gè)附近出發(fā)了CreateEventW的調(diào)用。同時(shí)這里先埋個(gè)包袱：注意OpenTraceW函數(shù)。

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

II. 線程大量創(chuàng)建銷毀的問(wèn)題的確認(rèn)

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

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

所以，根據(jù)現(xiàn)在掌握的證據(jù)來(lái)看，故事很有可能是這樣的：

1. 大量創(chuàng)建線程

2. 新創(chuàng)建的線程中又大量創(chuàng)建了Event

3. 創(chuàng)建的線程退出了，但是由于Event需要Manual Reset，所以Event并沒(méi)有被釋放

天下沒(méi)有免費(fèi)的午餐，這么大量的Event是需要內(nèi)存存放的。所以，大量創(chuàng)建線程導(dǎo)致cpu使用變高，大量創(chuàng)建未釋放的Event導(dǎo)致內(nèi)存使用變高。

看到這里你可能會(huì)說(shuō)，上面都是你的猜測(cè)，有什么證據(jù)支持么？下面我們?cè)谡{(diào)試器中驗(yàn)證我們上面的猜測(cè)。在正式開始之前，我想先闡述一下我的思路：上面的分析結(jié)論是，新創(chuàng)建的線程導(dǎo)致新創(chuàng)建了Event；所以，如果我們下兩個(gè)斷點(diǎn)，第一個(gè)斷點(diǎn)在sysmon+0x1820e處，第二個(gè)斷點(diǎn)在系統(tǒng)的CreateEventW函數(shù)上；那么，這兩個(gè)斷點(diǎn)應(yīng)該是交替命中；由于兩個(gè)斷點(diǎn)一個(gè)是位于sysmon模塊的線程函數(shù)地處，另外一個(gè)則為與系統(tǒng)的kernel32.dll模塊地址，所以兩個(gè)斷點(diǎn)理論上并沒(méi)有必然聯(lián)系，如果現(xiàn)象真的是兩個(gè)斷點(diǎn)交替命中，則可以驗(yàn)證我們上文的猜測(cè)。

下面是實(shí)際操作，首先是兩個(gè)斷點(diǎn)：

圖    8. 兩個(gè)斷點(diǎn)

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

圖 9. 斷點(diǎn)交替命中

可見現(xiàn)象與我們?cè)O(shè)想一致，印證了我們猜測(cè)的正確性?？赡?，有較真的讀者還是會(huì)說(shuō)，你現(xiàn)在說(shuō)的這些都還是間接證據(jù)。那么，接下來(lái)我們就和這個(gè)問(wèn)題剛一下正面，用代碼說(shuō)明問(wèn)題。

出現(xiàn)此問(wèn)題的根本證據(jù)

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

圖 10. 導(dǎo)致cpu過(guò)高線程的入口函數(shù)

這里說(shuō)一下關(guān)鍵邏輯，注意圖10中的第44行處的函數(shù)調(diào)用sub_140018360,以及本函數(shù)的地址sub_1400180e0。本代碼片段的意義是，在某個(gè)全局信號(hào)的作用下，有可能會(huì)調(diào)用到sub_140018360這個(gè)函數(shù)，同時(shí)給這個(gè)函數(shù)傳一個(gè)參數(shù)為1。

接下來(lái)看一下sub_140018360函數(shù)做了什么，為了方便說(shuō)明問(wèn)題，偽代碼做了部分折疊處理： 

圖 11. 導(dǎo)致遞歸調(diào)用的地方

注意69行的線程創(chuàng)建函數(shù)，也就是說(shuō)，在sub_140018360函數(shù)的參數(shù)為1的情況下，不出錯(cuò)，會(huì)走到69行的線程創(chuàng)建，線程的入口函數(shù)是sub_1400180e0。眼熟么？不眼熟的請(qǐng)看下圖10。也就是說(shuō)，sub_1400180e0最后會(huì)調(diào)用sub_140018360函數(shù)，而sub_140018360函數(shù)內(nèi)部創(chuàng)建了一個(gè)線程，創(chuàng)建的這個(gè)線程又調(diào)用回了sub_1400180e0函數(shù)，而由圖6的分析可知，正是由于sub_1400180e0里面的OpenTraceW函數(shù)導(dǎo)致創(chuàng)建了大量的Event，從而使內(nèi)存飆升。這是一個(gè)類似遞歸調(diào)用的邏輯，如果一致走下去，是不會(huì)有盡頭的。

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

1. 遞歸調(diào)用創(chuàng)建線程，導(dǎo)致cpu使用率飆升

2. 上面創(chuàng)建的線程通過(guò)OpenTraceW創(chuàng)建了大量Event，導(dǎo)致內(nèi)存飆升

至此，sysmon占用高cpu和高內(nèi)存的直接原因已經(jīng)找到。

三、什么原因?qū)е碌拇藛?wèn)題的產(chǎn)生

在調(diào)試過(guò)程中，發(fā)現(xiàn)如下幾個(gè)現(xiàn)象：

1. sysmon會(huì)重啟一次，且重啟后的sysmon才會(huì)有高cpu和內(nèi)存占用

2. sysmon重啟前TsService.exe會(huì)拉起幾個(gè)進(jìn)程，但是拉起的進(jìn)程結(jié)束的很快

看到這里，可能各位有個(gè)疑問(wèn)，TsService.exe是什么東西？答案是，此進(jìn)程為QQ瀏覽器的后臺(tái)服務(wù)進(jìn)程。證據(jù)如下（此可執(zhí)行文件有正常的騰訊簽名）：

圖 12. TsService.exe為QQ瀏覽器的服務(wù)進(jìn)程

然后，我跟進(jìn)了一下TsService.exe啟動(dòng)的那幾個(gè)進(jìn)程是什么：

圖 13. TsService.exe啟動(dòng)的子進(jìn)程

順帶一提，圖13中的子進(jìn)程，第一行沒(méi)截全的地方是：set-default-browser --slient  ;-）。嗯，接下來(lái)才是我們需要關(guān)注的點(diǎn)，幾個(gè)xperf子進(jìn)程的命令。

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

圖 14. 騰訊方面對(duì)xper參數(shù)的解釋

以及踩過(guò)的坑：

圖 15. 文中提到的啟動(dòng)失敗的情況

文中提到了ProcessMonitor和ProcessExplorer會(huì)導(dǎo)致xperf失敗，需要先關(guān)閉再啟動(dòng)。經(jīng)過(guò)我的測(cè)試，sysmon也是會(huì)導(dǎo)致xper.exe拋出上圖中相同的錯(cuò)誤。

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

還記得本節(jié)剛開始提到的兩個(gè)現(xiàn)象么——sysmon重啟后會(huì)出現(xiàn)高占用現(xiàn)象。難道和騰訊瀏覽器啟動(dòng)的xperf有關(guān)？

四、此問(wèn)題在任意機(jī)器上的復(fù)現(xiàn)

為了證明上面的猜測(cè)，我做了如下實(shí)驗(yàn)。

不賣關(guān)子，首先直接給出結(jié)論，通過(guò)xperf和sysmon的“協(xié)同配合”，可以在任何機(jī)器上復(fù)現(xiàn)sysmon高cpu和內(nèi)存占用的問(wèn)題。

具體步驟為：

1. 首先最好有一個(gè)全新安裝的純凈系統(tǒng)（可選）

2. 在系統(tǒng)上安裝sysmon服務(wù)，具體命令為,在管理員權(quán)限的cmd下執(zhí)行: sysmon -i

3. 停止sysmon的服務(wù)（因?yàn)椴煌Ｖ箷?huì)導(dǎo)致xperf命令報(bào)錯(cuò)）

4. 使用xperf.exe依次執(zhí)行如下命令:

5. 重新啟動(dòng)sysmon服務(wù)

上述步驟執(zhí)行完畢后，新啟動(dòng)的sysmon服務(wù)的cpu使用率會(huì)占滿一個(gè)邏輯核。內(nèi)存使用率也會(huì)慢慢的上去。

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

則sysmon的使用率則會(huì)降回到正常水平。

五、誰(shuí)關(guān)閉了sysmon？

通過(guò)上面的分析可知，此問(wèn)題出現(xiàn)的根本原因在于sysmon重啟后，所需要的資源（NT Kernel Logger）被占用，導(dǎo)致重啟后的sysmon服務(wù)無(wú)法拿到所需資源，一直在重試。那么到底是什么原因?qū)е聅ysmon退出呢？

結(jié)合上文的分析，我將排查重點(diǎn)放在了TsService.exe服務(wù)上。通過(guò)對(duì)TsService.exe 進(jìn)程的OpenServiceW函數(shù)下斷點(diǎn)，最終將問(wèn)題定位到了PerfTool.dll這個(gè)模塊中:

圖 16. 關(guān)閉sysmon服務(wù)

六、此問(wèn)題的解決方案（部分）

I. 方案一

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

通過(guò)圖10中的第43和44行可以知道，在調(diào)用導(dǎo)致“遞歸”的函數(shù)之前，還有一個(gè)if判斷，這個(gè)判斷用sub_14008da0(我已經(jīng)改名為fnReadRegistryValue)的返回值，與1做邏輯與操作，只有這個(gè)操作為真的情況下才會(huì)產(chǎn)生“遞歸”的邏輯。接下來(lái)，我們看一下fnReadRegistryValue這個(gè)函數(shù)干了啥：

圖 17. 讀取注冊(cè)表中的配置項(xiàng)

可以看到，該函數(shù)的返回值為Data，而Data中的數(shù)據(jù)來(lái)自于注冊(cè)表的如下鍵值：

如果此鍵值的值，與1做與運(yùn)算為0的話，即可結(jié)束“遞歸”的邏輯。也就是說(shuō)，如果這個(gè)鍵值下的數(shù)值是偶數(shù)，則永遠(yuǎn)都不會(huì)因?yàn)檫@兩個(gè)函數(shù)的“遞歸”調(diào)用，從而不會(huì)產(chǎn)生高cpu和內(nèi)存占用的問(wèn)題。

那么這個(gè)鍵值是干什么用的呢？從sysmon的幫助文檔可知，sysmon是一個(gè)命令行工具，是有啟動(dòng)參數(shù)的，結(jié)合Options的意義，可知不同的sysmon監(jiān)控啟動(dòng)參數(shù)，會(huì)導(dǎo)致這個(gè)值的不同。后來(lái)的實(shí)驗(yàn)也證實(shí)這個(gè)鍵值的確會(huì)根據(jù)sysmon的啟動(dòng)參數(shù)不同而不同。

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

II. 方案二

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

正如產(chǎn)生本文性能問(wèn)題的“遞歸”問(wèn)題一樣。本來(lái)是性能排查的行為，卻最終導(dǎo)致了性能問(wèn)題，而后需要繼續(xù)進(jìn)行性能問(wèn)題的排查......而此問(wèn)題的出現(xiàn)，并不是由單一因素導(dǎo)致，而是多種因素共同作用的結(jié)果。由于性能測(cè)試的特殊性，并不是所有的機(jī)器都需要進(jìn)行這項(xiàng)測(cè)試，所以初始化的那個(gè)行為：關(guān)閉sysmon，啟動(dòng)xperf進(jìn)行性能信息收集，并不會(huì)在每一臺(tái)機(jī)器上執(zhí)行。所以，這個(gè)問(wèn)題的出現(xiàn)，有一定的“隨機(jī)”性，并不是在每臺(tái)機(jī)器上必現(xiàn)。

看完上述內(nèi)容，你們對(duì)Sysmon占用CPU及內(nèi)存過(guò)高問(wèn)題分析與解決方法有進(jìn)一步的了解嗎？如果還想了解更多知識(shí)或者相關(guān)內(nèi)容，請(qǐng)關(guān)注億速云行業(yè)資訊頻道，感謝大家的支持。