一次由QQ瀏覽器效能分析引起的效能問題
一、背景
最近有個專案用到了sysinternals出品的監控工具：sysmon.exe。但是有反饋，sysmon.exe程序（下文為方便描述簡稱為sysmon）在某一特定條件下，持續佔用cpu，一般為會跑滿cpu的一個邏輯核。例如，如果cpu為雙核4執行緒，則sysmon的佔用在25%。且sysmon佔用的記憶體持續升高。
本文中的圖是在除錯環境中隨本文的編寫而截的，所以各位看到圖中的sysmon程序PID不一致。
圖 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子程序的命令。
寫到這裡，插個題外話，在解決這個問題查資料的過程中，查到過這麼一篇資料： ofollow,noindex" target="_blank">《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進行效能資訊收集，並不會在每一臺機器上執行。所以，這個問題的出現，有一定的“隨機”性，並不是在每臺機器上必現。
*本文作者：京東安全，轉載請註明來自FreeBuf.COM