Sysmon占用CPU及内存过高问题分析与解决 – 作者:京东安全

一、背景

最近有个项目用到了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子进程的命令。

写到这里，插个题外话，在解决这个问题查资料的过程中，查到过这么一篇资料：《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

来源：freebuf.com 2018-09-13 10:00:18 by: 京东安全