标准实施方案下的异常发现
生产系统上线实施了这么多年,也算半个硬件方面的专家,而这次的发现让我对硬件、操作系统的认识又上了一个台阶。
某次通过装机平台刚刚安装完windows 2016 后,操作时系统出现卡顿现象。于是先将设备下架,后更换另外两台服务器。通过光盘手动安装后,升级相应的最新固件及网卡、HBA卡驱动,接入互联网更新最新安全补丁。经观察,系统卡顿现象消失,但发现有CPU资源管理器不平稳现象,结合任务管理器查看是WMI进程占用,具体抖动的现象如图:
抽丝剥茧发现问题真相
发现了问题,我们逐步深入排查。中医上讲究望闻问切,同样的针对服务器,我们按照由表及里的方式,逐层深入。
首先我们通过服务器管理口抓取硬件日志,经过分析硬件的日志,并未发现硬件有故障,我们将硬件层面的问题排除。
接下来,我们深入软件层面,对其进行诊脉。
在CPU问题复现的时候,我们按照以下步骤收集的系统日志:
1、先下载微软官方的process monitor和procdump工具,并将附件的.txt文件后缀修改为.ps1,拷贝到服务器的某个文件夹,建议新建一个C:\mstrace文件夹,后续的指令依赖这个目录。
2、以管理员权限打开cmd,运行如下命令开启日志收集(如果需要修改目录位置,修改标黄的路径):
3、在WMI provider host进程CPU较高的时候,以管理员运行Wmi-Collect.ps1,这个会在当前目录下打包生成一份日志
4、待脚本执行完成后,运行如下命令停止trace收集:
wpr.exe -stop C:\mstrace\wpr.etl
procmon /terminate
logman stop "admin_wmi" -ets
wevtutil set-log "Microsoft-Windows-WMI-Activity/Trace" /enabled:false
wevtutil export-log "Microsoft-Windows-WMI-Activity/Trace" C:\mstrace\%computername%_WMI-Activity-Trace.evtx
5、收集perfmon 日志
以管理员打开cmd,输入以下命令,然后按回车键:
Logman.exe create counter Perf-1second -f bincirc -max 2048 -c "\LogicalDisk(*)\*" "\Memory\*" "\Network Interface(*)\*" "\Paging File(*)\*" "\PhysicalDisk(*)\*" "\Server\*" "\System\*" "\Process(*)\*" "\Thread(*)\*" "\Processor(*)\*" "\Processor Information(*)\*" "\Cache\*" -si 00:00:01 -o C:\PerfMonLogs\Perf-1second.blg
(说明:日志会循环写,单个日志最大是2GB,存放在C:\PerfMonLogs\)
在使用以上命令设置完成之后,输入以下命令开启计数器:
logman start Perf-1second
2分钟后,请输入以下命令停止性能日志:
logman stop Perf-1second
6、收集WPR 日志
wpr.exe -start GeneralProfile -start CPU -filemode
等两分钟后执行wpr.exe -stop c:\1.etl
分析系统日志
从WPR来看,WmiPrvSE.exe (6276)的占用权重最高,占用平均权重0.11,且与资源管理器显示的一样呈现间隔性冲高:
这里面冲高的权重全部来自于以下的WMI查询,可以看到大概是每隔10秒钟冲高一次。
从WMI-Activity/Trace Event Log中也看到大量的相关查询,大概也是10秒钟一次。
目前看到发起该查询的为以下的进程 PID 3628。
这个查询命令是一个轮询的查询命令,查询为10秒一次。
winmgmt的dump钟也可以看到这个WMI请求,来源也是PID 3268。
查看进程PID 3628的身份:
这个进程IPROSetMonitor.exe应该是开机启动的,然后启动后就发送了一条每隔10秒查询一次的WMI请求导致了该问题的出现。
定位原因
综合上面日志来看,导致问题的是因为PID 3628 IPROSetMonitor.exe 在进行WMI查询,查询命令如下:
SELECT * FROM __InstanceOperationEvent WITHIN 10 WHERE (TargetInstance ISA 'Win32_NetworkAdapter')
这个命令有轮询机制,所以会每10秒查询一次。
IPROSetMonitor.exe 是个Intel相关的服务Intel(R) PROSet Monitoring Service
对症下药,药到病除
通过一系列的日志收集分析判断,找到了“病理”所在,我们在services.msc中停止IPROSetMonitor.exe 服务后,CPU冲高的问题得以缓解,至此CPU使用率抖动的问题被彻底治愈。
看似不大的问题,却耗时很长时间去排查。本次认知的过程离不开公司提供的强有力的支持,以及各团队人员的密切配合。认知永无止境,在不断前进的路上,需要我们不断探索,也希望本次发现的问题,能够作为后期运维工作上的一点借鉴。

