es服务器的cpu压力过大的调试

问题简述

最近观察到es集群的压力比较大。cpu使用经常报警，cpu使用超过90%时间持续3分钟会报警。
于是想要针对性的排查一下问题。

确认一下目前的cpu压力是否是一种因为请求量过大导致的正常压力。
评价现有的cpu压力是一个什么样的状态，是否需要进行扩容来减轻压力。

过程

1. 机器的配置梳理

机器的配置为16+64G+6Tssd的服务器
1.查看cpu的基本信息

lscpu
Architecture:          x86_64
CPU op-mode(s):        32-bit, 64-bit
Byte Order:            Little Endian
CPU(s):                16
On-line CPU(s) list:   0-15
Thread(s) per core:    1
Core(s) per socket:    16
Socket(s):             1
NUMA node(s):          1
Vendor ID:             GenuineIntel
CPU family:            6
Model:                 94
Model name:            Intel(R) Xeon(R) Gold 61xx CPU
Stepping:              3
CPU MHz:               2494.138
BogoMIPS:              4988.27
Hypervisor vendor:     KVM
Virtualization type:   full
L1d cache:             32K
L1i cache:             32K
L2 cache:              4096K
NUMA node0 CPU(s):     0-15

能看出来是16核 2.5GHZ

2. cpu使用分析

2.1 使用vmstat查看cpu使用的总体情况

vmstat 1 10
procs  -----------memory----------   ---swap-- -----io---- --system---     -----cpu-----r  b   swpd   free   buff  cache     si   so    bi    bo   in     cs     us sy id wa st8  0      0 360636 277324 28147252    0    0   748  4564    0      0 32   4 64  0  0
11  0      0 378904 277368 28128972    0    0  2312 52400  32592   16954  47  5 48  0  09  0      0 370612 277492 28136304    0    0  2120 71848  35218   22522  51  9 40  0  06  2      0 362264 277588 28143432    0    0  4244 261056 51937   24833  49  6 43  2  0
15  0      0 358552 277628 28150412    0    0  4868 603260 77023   37910  51  8 36  5  0
25  2      0 493480 277628 28013572    0    0  6352 106680 219626  30016  84  9  7  0  0
20  1      0 753788 277728 27754924    0    0  6396 76712  68957   22943  55  6 39  0  05  0      0 716852 277856 27791392    0    0  1352 53368  27737   19543  35  3 62  0  0
14  2      0 652308 277916 27854852    0    0  6288 22012  14310   8217   23  2 75  0  0
19  2      0 613420 278052 27893748    0    0   184 270524 45331   34330  38  5 55  2  0

实际采集的时候需要采集更多的数据会更好
从这里可以看到procs-r 等待被执行的队列中的线程数量稍微有一点多，但是cpu的核数是16，相对来说还好
system-cs 上下文的切换次数也比较多，这个次数越高对应的内核的消耗可能会越大。
但是从这里看内核态对cpu的占用算是比较合理的。然后看cpu的id,总体还可以，us 50左右，对于当前的es服务（计算密集+io密集）来说算是比较高的压力。和运维同学沟通了一下。他们给的建议是

这个没有定数。一般情况下cpu密集型的应用cpu的idle 低于20%，可能就会影响到服务的性能。
对于存储而言如MySQL/Monog这种cpu idle低于50%，就会有明显的影响。

2.2 查看业务对cpu的使用情况

jps
2084 Jps
19994 Elasticsearch

 top -Hp 19994
top - 17:15:49 up 30 days,  1:13,  1 user,  load average: 7.42, 7.06, 7.35
Tasks: 336 total,   0 running, 336 sleeping,   0 stopped,   0 zombie
Cpu(s): 50.9%us,  4.2%sy,  0.0%ni, 43.7%id,  0.4%wa,  0.0%hi,  0.8%si,  0.0%st
Mem:  65972900k total, 65610864k used,   362036k free,   295212k buffers
Swap:        0k total,        0k used,        0k free, 28135532k cachedPID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
31037 deploy    20   0 1568g  36g 2.6g S 46.1 57.3   1:10.06 java
20450 deploy    20   0 1568g  36g 2.6g S 37.8 57.3   9019:13 java
20460 deploy    20   0 1568g  36g 2.6g S 37.8 57.3   9019:38 java
20456 deploy    20   0 1568g  36g 2.6g S 36.8 57.3   9026:49 java
20449 deploy    20   0 1568g  36g 2.6g S 36.2 57.3   9024:29 java
20458 deploy    20   0 1568g  36g 2.6g S 36.2 57.3   9020:39 java
20463 deploy    20   0 1568g  36g 2.6g S 36.2 57.3   9024:01 java
20447 deploy    20   0 1568g  36g 2.6g S 35.8 57.3   9015:24 java
20453 deploy    20   0 1568g  36g 2.6g S 35.8 57.3   9032:01 java
20459 deploy    20   0 1568g  36g 2.6g S 35.5 57.3   9020:07 java
20462 deploy    20   0 1568g  36g 2.6g S 34.9 57.3   9024:01 java
20466 deploy    20   0 1568g  36g 2.6g S 34.5 57.3   9025:11 java
20451 deploy    20   0 1568g  36g 2.6g S 33.9 57.3   9017:45 java
20461 deploy    20   0 1568g  36g 2.6g S 33.9 57.3   9019:00 java
20464 deploy    20   0 1568g  36g 2.6g S 33.5 57.3   9020:45 java
20465 deploy    20   0 1568g  36g 2.6g S 33.5 57.3   9022:40 java
20457 deploy    20   0 1568g  36g 2.6g S 33.2 57.3   9018:58 java
20448 deploy    20   0 1568g  36g 2.6g S 32.9 57.3   9018:38 java
20431 deploy    20   0 1568g  36g 2.6g S 11.3 57.3   2087:41 java
20434 deploy    20   0 1568g  36g 2.6g S 10.6 57.3   2320:50 java3909 deploy    20   0 1568g  36g 2.6g S 10.6 57.3 256:17.99 java
20411 deploy    20   0 1568g  36g 2.6g S 10.3 57.3   1567:51 java
20415 deploy    20   0 1568g  36g 2.6g S 10.3 57.3   1605:27 java
20432 deploy    20   0 1568g  36g 2.6g S 10.3 57.3   2449:51 java
20409 deploy    20   0 1568g  36g 2.6g S 10.0 57.3   1962:21 java
20430 deploy    20   0 1568g  36g 2.6g S  6.6 57.3 443:30.90 java
20425 deploy    20   0 1568g  36g 2.6g S  6.3 57.3   2472:08 java4224 deploy    20   0 1568g  36g 2.6g S  6.0 57.3 312:00.58 java
20454 deploy    20   0 1568g  36g 2.6g S  5.3 57.3 257:35.44 java3833 deploy    20   0 1568g  36g 2.6g S  5.0 57.3 269:26.03 java3860 deploy    20   0 1568g  36g 2.6g S  5.0 57.3 318:05.67 java
...
...

这里可以看到,cpu资源暂用率较高的总共有17个线程，但是没有单个线程占用cpu超高的情况。
因为这里es做的是日志服务器，猜测是写入线程占用较高的cpu,写入线程池刚好是17.
当然并不一定完全是写入线程，拿出来一个看看。

2.3 查看对应的线程相关信息

因为jstack中显示的线程号是16进制的，所以需要先转成16进制的

printf '%x' 20462
4fee

然后使用jstack过滤

jstack -l 19994 |grep '4fee' -A5"elasticsearch[ESV05][write][T#13]" #104 daemon prio=5 os_prio=0 tid=0x00007efbf8028800 nid=0x4fee runnable [0x00007efb4e9e1000]java.lang.Thread.State: RUNNABLEat org.wltea.analyzer.core.AnalyzeContext.outputToResult(AnalyzeContext.java:294)at org.wltea.analyzer.core.IKSegmenter.next(IKSegmenter.java:129)- locked <0x00000001878dd3e8> (a org.wltea.analyzer.core.IKSegmenter)at org.wltea.analyzer.lucene.IKTokenizer.incrementToken(IKTokenizer.java:88)

可以看到确实是一个write线程。