一次线上服务器cpu使用率超过1250%的排查与优化

小鱼儿 2022-01-12 11:37 311阅读 0赞

*  **项目背景：**

将35家海外酒店的房型数据通过40个定时任务同步到本地mongodb，这里用了5台服务器来部署项目，mongodb采用分片集群部署。定时任务采用lts，一个小时同步一次所有数据。项目中用多线程按天来同步35家酒店的365天的数据，高峰期可能会同时存在几百个线程在同时处理任务，项目上线之后mongodb服务器就出现问题了。

*  **项目服务器部署架构：**

![watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM1ODU5ODQ0_size_16_color_FFFFFF_t_70][]

先来看一下运维反馈的服务器cpu监控图：

![watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM1ODU5ODQ0_size_16_color_FFFFFF_t_70 1][]

上图是3台mongodb分片部署的服务器cpu使用率，9:00左右大量的定时任务开始执行，此时cpu使用率就开始飙升。

**第一次优化：**

** **给mongodb数据库加索引，但是效果不佳，此时的cpu使用率还是很高。

** **![watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM1ODU5ODQ0_size_16_color_FFFFFF_t_70 2][]

** 第二次优化：**

给mongodb数据库加分片键，由于mongodb是分片集群部署的，所以此时可以充分利用机器的优势来更新、删除mongodb数据，此时的效果有一些，但是不是很好。

![watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM1ODU5ODQ0_size_16_color_FFFFFF_t_70 3][]

此时还是会一段时间内cpu使用率很高的情况，但是比之前好多了。

**第三次优化：**

1.在代码中加入监控，观察比较耗时的代码模块以便排查问题所在。

![watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM1ODU5ODQ0_size_16_color_FFFFFF_t_70 4][]

下面是慢查询日志

![watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM1ODU5ODQ0_size_16_color_FFFFFF_t_70 5][]

从代码监控和mongodb的慢查询日志来看，删除一条数据居然需要花费4秒钟，导致cpu飙升的应该是删除旧数据时候的查询比较耗时，由于删除的频率比较高，导致cpu一直在执行。

**此时考虑到应该是两个地方不足：**

a.索引没有被利用到,需要重建索引。

b.删除比较频繁、耗时，不能影响到主程序的执行，应该把删除逻辑放入kafka队列中执行。

2.程序优化如下：

a.重建更新和删除索引。

b.将主程序的删除操作改成逻辑删除，标记需要删除的数据，放入kaka队列。

c.新建定时任务，在23:59:59批量删除标记的数据。

经过优化之后明显的能看到，每个线程的更新mongodb的逻辑耗时明显减少

![watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM1ODU5ODQ0_size_16_color_FFFFFF_t_70 6][]

此时，cpu的使用率从最开始的1250%回归到正常状态，从7月4号12点之后cpu使用率正常，磁盘的使用率也回归正常，显然此次优化效果显著。

![watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM1ODU5ODQ0_size_16_color_FFFFFF_t_70 7][]

**总结：**

**  1.mongodb删除操作比较耗时，应当将删除操作剥离主程序执行并建立合理的索引。**

**  2.在代码中加入耗时监控可以更加准确的定位到问题所在。**

--------------------

以上是因为已经定位到代码中的哪个地方导致cpu使用率超高，一般的定位代码导致cup过高的方法如下：

*  通过top命令找到cpu占用高的进程pid

![watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM1ODU5ODQ0_size_16_color_FFFFFF_t_70 8][]

这里进程号为21038占用cpu过高

*  top -H -p 进程号Pid（通过进程号找到该进程下占用cpu过高的线程号）

top -H -p 21038

![20190722105957359.png][]

这里线程号为21125占用cpu过高

*  printf "%x\\n" 线程号Pid（将线程号Pid转换为16进制）

printf "%x\\n" 21125

![20190722110332733.png][]

*  jstack 进程号|grep 16进制线程号  -A50 (-A50 日志最后50行)

jstack 21038|grep 5285 -A50

![20190722110608548.png][]

定位到代码中，发现代码中有个死循环，导致该线程一直抢占cpu。

[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM1ODU5ODQ0_size_16_color_FFFFFF_t_70]: /images/20220109/e7d5595f409b4156ba08dab0048e5265.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM1ODU5ODQ0_size_16_color_FFFFFF_t_70 1]: /images/20220109/c88b799cefb84f75bbdb461c3aa46281.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM1ODU5ODQ0_size_16_color_FFFFFF_t_70 2]: /images/20220109/fb8396ac8713456a919b520b98b8a7ef.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM1ODU5ODQ0_size_16_color_FFFFFF_t_70 3]: /images/20220109/e79a3fadafbc4703b77313c009338f51.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM1ODU5ODQ0_size_16_color_FFFFFF_t_70 4]: /images/20220109/ea0a778a7f4541eda4b0251982ee12ff.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM1ODU5ODQ0_size_16_color_FFFFFF_t_70 5]: /images/20220109/b089190eb30f4df8ad6dea2d4be5472f.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM1ODU5ODQ0_size_16_color_FFFFFF_t_70 6]: /images/20220109/ebac3fc831ab4b448211066572657b11.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM1ODU5ODQ0_size_16_color_FFFFFF_t_70 7]: /images/20220109/78b75820dead4f93a758512dab3d7e9b.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM1ODU5ODQ0_size_16_color_FFFFFF_t_70 8]: /images/20220109/f1bbd9f8b1cc4f0887b490169319cb73.png
[20190722105957359.png]: /images/20220109/8c3477464f524e5498a7851c81477dab.png
[20190722110332733.png]: /images/20220109/10dc6fddc4d149faab50c3021d0f58ca.png
[20190722110608548.png]: /images/20220109/dddaa9f887b64c90b78581e71df47227.png