Watch & Learn

Debugwar Blog

Step in or Step over, this is a problem ...

一次由QQ浏览器性能分析引起的性能问题

2022-03-11 01:44:38

这是一篇旧文,为博主供职于京东时由京东安全发表在各大平台的一篇文章。近期在整理电脑硬盘时发现躺在角落里的word文件,因此汇总到博客中来。

背景

最近数据泄密事件频发,勒索蠕虫的新闻也时不时占据各大资讯网站IT板块头条的位置。网络安全问题日益突出,应对这些问题成了安全从业人员当前最紧迫的任务。数据泄密、勒索蠕虫、黑客入侵……此类问题发现的越早其所造成的损失便会越小。相信各位在日常工作中也遇到过相类似的问题,而处理这些问题的过程中必然会跟各类日志打交道,如何生成一份合格的日志会起到令安全运维人员工作事半功倍的效果。

当前市面上有很多的日志收集工具,下表是我们调研的几个工具对比:

 名称

是否开源

是否免费

是否跨平台

收集能力

部署难度

osquery

Apache-2.0

中高

中高

audit

GPL & LGPL

中高

Windows系统日志

不单独收费

容易

sysmon

自己的协议

容易

qradare

未知

zabbix

GPLv2

nagios

根据版本

中低

ObserveIT

未知


经过对部署难度和收集能力的评估,某项目中我们使用了由sysinternals出品的监控工具:sysmon.exe(下文为方便描述简称为sysmon)。然而经过一段时间的使用之后收到反馈,sysmon有高CPU高内存占用的情况出现:一般为sysmon会跑满cpu的一个逻辑核。例如,如果cpu为双核4线程,则sysmon的占用在25%。且sysmon占用的内存持续升高。这个问题并不是在所有的机器上出现,而是有一定的“随机”性。

下图是sysmon出现上述问题时,在ProcessExplorer中观察到的cpu和内存使用情况的截图(本文中的图是在调试环境中随本文的编写而截的,所以各位看到图中的sysmon进程PID不一致)。

图 1. sysmon的高cpu、内存占用

问题定位与分析

分析思路

对于高CPU占用的问题,众所周知:cpu用来执行程序的指令,而程序(Process,进程)又可以继续拆分成线程。高CPU占用,最终一定会反映为某一个或几个线程持续占用cpu这个计算资源,所以我们需要优先关注线程的各个性能指标。

对于高内存占用的问题,这个定位起来就略微复杂了。由于程序运行过程中会向内存存放各种类型的数据,所以很难确定多出来的这些内存被用来做了什么。但是这并不意味着无从下手,程序还是有很多关键的性能指标可以间接的反映内存的使用情况,而且调试器也为我们提供了丰富的内存统计命令,可以让我们了解程序在运行过程中的内存使用情况

问题初步定位

根据上文思路中提到的,在ProcessExplorer观察sysmon进程各个线程的cpu使用情况,如下图:

图 2. 红色为线程销毁、绿色为线程创建

发现各个线程的cpu占用率并不高,但是却有大量的新线程被创建,同时又有大量的旧线程被销毁。可见,cpu时间片被主要用于线程的创建、销毁操作了。

对于内存问题,在ProcessExplorer中观察sysmon的性能页,发现句柄数量异常的高,竟然在非常短的时间内达到了万的量级,如下图中红框内的数值:

图 3. 句柄数量异常

所以接下来的分析重点将围绕线程的大量创建和销毁以及句柄的异常创建展开。

调试器中定位问题

为了印证上文中在ProcessExplorer观察到的现象,我们需要在调试器中进一步确认。其基本思路为:由创建线程的动作,往回找,直到找到创建线程所在的函数。下面我们分两步来分别收集一些这方面的初步信息。

定位线程大量创建销毁的问题

使用如下命令打印sysmon所以线程的堆栈回溯:

  1. ~*kb  

得到的栈回溯如下图:

图 4. 定位到出问题的函数

从上文的图2可知,创建的线程都是以sysmon.exe+0x494a8这个地址开始的。顺着这个线索摸过去,发现图4中sysmon+0x495aa这个堆栈返回地址,范围落在sysmon.exe+0x494a8这个函数的范围内。顺着sysmon+0x495aa这个栈回溯线索往回找,最终确定sysmon+0x1820e为出问题的函数。

分析进行到这里先暂时告一段落,稍后再验证分析的是否正确。接下来,跟进第二个问题:内存占用过高。

定位内存占用过高问题

由上文中图3可知,sysmon在段时间内创建了大量的句柄。所以,我在调试器中调查了一下这些句柄的使用情况,如图:

图 5. 句柄全局统计

从图5中可以看到,短短几分钟之内,句柄数目由图3的4.5万多个增加到现在的72942个,其中Event类型的句柄占了72878个,比例高达99%,而且这些event都需要人工重置状态。这隐含着一个信息,在程序没有人工重置这些event的状态前,event不会被释放。短时间内创建如此量级的事件且不释放,时间久了,内存占用自然就上去了。

在调试器中确认问题

内存占用过高问题的确认

通过上一节的分析,我们初步定位了cpu以及内存占用过高的原因。接下来我们来确定一下,是否是因为这个原因导致的。趁着各位刚看完内存占用过高的问题,我们先从这个问题入手。

熟悉windows编程的人可以知道,创建event一般会调用CreateEvent这个函数。那么我们在此函数上下如下断点:

  1. bu kernel32!CreateEventW “k;g”  

解释一下这个断点的意思:首先断在kernel32.dll中的CreateEventW函数调用的开始,然后打印一下堆栈调用,最后恢复程序的执行。

OK,下图是执行结果的一部分:

图 6. 在创建Event时获取栈回溯调用

图6是大概执行了5秒钟左右的样子,从右边下拉条来看输出大概有几千条,也就是5秒钟内创建了几千个Event,这和我们上面观察到的句柄暴增现象项符。往上翻一下每次的栈回溯输出,发现都是sysmon+0x181b7这个附近触发了CreateEventW的调用。同时这里先埋个包袱:注意OpenTraceW函数。

这里同样还有另外一个需要注意的地方,就是图6中的最后一个sysmon模块的函数调用返回地址:sysmon+0x181b7。结合图4中我们定位的,离导致新线程不停被创建的地址sysmon+0x1820e很近。至于这两个地址的因果关系,详见下文分析。

线程大量创建销毁的问题的确认

刚才提到 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_14为:由创建线程的动作,往回找,直到找到创建线程所在0018360,以及本函数的地址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启动的子进程

上提中我们需要关注TsService.exe启动的几个xperf子进程。

写到这里,插个题外话,在解决这个问题查资料的过程中,查到过这么一篇资料:《QQ浏览器性能提升之路-windows性能分析工具篇》。这篇文章给出了图13中xperf命令的详细解释:

图 14. 腾讯方面对xper参数的解释

以及踩过的坑:

图 15. 文中提到的启动失败的情况

文中提到了ProcessMonitor和ProcessExplorer会导致xperf失败,需要先关闭再启动。经过我的测试,sysmon也是会导致xper.exe抛出上图中相同的错误。

再插一个题外话,xperf为微软官方提供的性能信息收集工具,借助此工具可以分系windows系统上程序的许多性能问题。

还记得本节刚开始提到的两个现象么——sysmon重启后会出现高占用现象。难道和腾讯浏览器启动的xperf有关?

此问题在任意机器上的复现

上文中我们已经有了此问题产生原因的初步设想。随后,我人工模拟TsService.exe启动的xperf命令顺序以及sysmon进程退出重新启动这一现象。成功在任意机器上复现了sysmon高cpu和内存占用的问题。 具体步骤为:
  • 首先最好有一个全新安装的纯净系统(可选)
  • 在系统上安装sysmon服务,具体命令为,在管理员权限的cmd下执行: sysmon -i
  • 停止sysmon的服务(因为不停止会导致xperf命令报错)
  • 使用xperf.exe依次执行如下命令:
  1. xperf.exe -stop  
  2. xperf.exe -start -on disk_io+disk_io_init+filename+proc_thread  
  • 重新启动sysmon服务
上述步骤执行完毕后,新启动的sysmon服务的cpu使用率会占满一个逻辑核。内存使用率也会慢慢的上去。

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

  1. xperf.exe -stop  

这样之后sysmon的使用率则会降回到正常水平。

谁关闭了sysmon?

通过上面的分析可知,此问题出现的根本原因在于sysmon重启后,所需要的资源(NT Kernel Logger)被占用,导致重启后的sysmon服务无法拿到所需资源,一直在重试。那么到底是什么原因导致sysmon退出呢?

结合上文的分析,我将排查重点放在了TsService.exe服务上。通过对TsService.exe 进程的OpenServiceW函数下断点,最终将问题定位到了PerfTool.dll这个模块中:

图 16. 关闭sysmon服务

此问题的解决方案(部分)

方案一

注意,这里只是根据上文中的分析,提出几种解决方案,不是最终的唯一解决方案。

通过图10中的第43和44行可以知道,在调用导致“递归”的函数之前,还有一个if判断,这个判断用sub_14008da0(我已经改名为fnReadRegistryValue)的返回值,与1做逻辑与操作,只有这个操作为真的情况下才会产生“递归”的逻辑。接下来,我们看一下fnReadRegistryValue这个函数干了啥:

图 17. 读取注册表中的配置项

可以看到,该函数的返回值为Data,而Data中的数据来自于注册表的如下键值:

  1. HKLM\\System\\CurrentControlSet\\Services\\SysmonDrv\\Parameters\\Options  

如果此键值的值,与1做与运算为0的话,即可结束“递归”的逻辑。也就是说,如果这个键值下的数值是偶数,则永远都不会因为这两个函数的“递归”调用,从而不会产生高cpu和内存占用的问题。

那么这个键值是干什么用的呢?从sysmon的帮助文档可知,sysmon是一个命令行工具,是有启动参数的,结合Options的意义,可知不同的sysmon监控启动参数,会导致这个值的不同。后来的实验也证实这个键值的确会根据sysmon的启动参数不同而不同。

所以,一个可行的解决方案是,当cpu占用很高且内存在缓慢上升时,可以暂时将该键值置为0,使程序跳出“递归”逻辑,然后再将此值改回原来的值,以免影响其监控需求。

方案二

由图16可知, TsService.exe关闭sysmon使用的是硬编码。而sysmon是支持安装服务时使用其他服务名的。所以,另外一个可行的解决方案是安装sysmon服务时,使用其他的服务名,防止被TsService.exe关闭。

总结

监控这一需求伴随着运维而来,然而想要把监控做好,却不是一件容易的事。正如本文分析的sysmon性能问题一样。原本以为sysmon作为Sysinternals这种微软子公司“官方”出品的工具应该很稳定,然而由于当前软件运行环境越来越复杂,工具的一些运行机制所需要的环境有可能会被破坏,而这种情况一旦出现,轻则导致程序退出,重则会影响整个系统。

对于监控类项目,一般需要配套一个运维后台,针对系统的基本指标做一些必要的监控,一旦发现监控的指标异常,需要发出告警以便让运维人员及时介入从而控制损失。当然,在这之前,也可以加入一些自动恢复的机制从而可以将问题扼杀在萌芽阶段。

根据笔者了解, sysmon还算是应用较为广泛的一款监控工具,希望本文提到的性能问题以及解决此问题的思路和方法,对各位有所帮助。
Catalog
  • 背景
  • 问题定位与分析
  • 分析思路
  • 问题初步定位
  • 调试器中定位问题
  • 定位线程大量创建销毁的问题
  • 定位内存占用过高问题
  • 在调试器中确认问题
  • 内存占用过高问题的确认
  • 线程大量创建销毁的问题的确认
  • 出现此问题的根本证据
  • 什么原因导致的此问题的产生
  • 此问题在任意机器上的复现
  • 谁关闭了sysmon?
  • 此问题的解决方案(部分)
  • 方案一
  • 方案二
  • 总结
  • CopyRight(c) 2020 - 2025 Debugwar.com

    Designed by Hacksign