1. 前言
最近k8s生产环境整体负载持续在很高的水位，此问题会导致应用启动时间过长从而导致pod启动失败，并且影响集群所有应用的运行效率，需要尽快定位到问题根源。
2. 定位问题
经过沟通以及排查，我们发现：172.16.9.195节点1分钟load高达45，而此节点的配置为8C/64GB。这样的负载已经是很高了，迫切需要进行优化
$ top - 14:34:56 up 932 days, 23:57, 1 user, load average: 45.89, 41.83, 38.25
Tasks: 241 total, 1 running, 240 sleeping, 0 stopped, 0 zombie
%Cpu(s): 61.3 us, 7.6 sy, 0.0 ni, 27.4 id, 0.0 wa, 0.0 hi, 3.6 si, 0.0 st
KiB Mem : 65976636 total, 4713772 free, 41757256 used, 19505608 buff/cache
KiB Swap: 0 total, 0 free, 0 used. 23686668 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
8727 root 20 0 11.9g 6.2g 10436 S 165.6 9.8 2420:42 java
23525 root 20 0 9864104 4.5g 10220 S 164.2 7.1 15681:36 java
24177 root 20 0 7171172 2.2g 9752 S 107.6 3.6 12076:04 java
17086 root 20 0 9881056 4.5g 10524 S 46.0 7.2 595:16.55 java
22195 root 20 0 9262612 3.4g 10348 S 38.1 5.5 267:17.53 java
3891 root 20 0 9932.6m 4.5g 9684 S 17.2 7.1 2826:10 java
1788 root 20 0 9102056 2.6g 11160 S 10.9 4.1 8:10.08 java
1660 root 20 0 5832736 904860 21556 S 9.9 1.4 69179:41 dockerd
3936 root 20 0 3650784 130264 23548 S 7.3 0.2 78787:15 kubelet
19873 root 20 0 9458468 2.8g 10428 S 6.3 4.4 70:30.53 java
68 root 39 19 0 0 0 S 4.0 0.0 1312:02 khugepaged
14540 root 20 0 1145376 216332 15616 S 3.6 0.3 3536:29 ilogtail
4053 root 10 -10 151228 33936 10612 S 2.0 0.1 3157:28 AliYunDunMonito
3 root 20 0 0 0 0 S 1.3 0.0 22133:15 ksoftirqd/0
23172 root 20 0 9184824 4.2g 9588 S 1.0 6.7 194:10.94 java
7 root 20 0 0 0 0 S 0.7 0.0 6099:02 rcu_sched
315 root 20 0 162148 4468 3664 R 0.7 0.0 0:08.21 top
1367 root 20 0 1022444 19184 452 S 0.3 0.0 5724:49 /usr/local/clou
4032 root 10 -10 102676 12024 8448 S 0.3 0.0 434:03.11 AliYunDun
23574 root 20 0 8306252 1.5g 9632 S 0.3 2.3 56:01.46 java
1 root 20 0 52596 4664 2384 S 0.0 0.0 870:26.31 systemd
2 root 20 0 0 0 0 S 0.0 0.0 1:32.01 kthreadd
8 root 20 0 0 0 0 S 0.0 0.0 0:00.00 rcu_bh
9 root 20 0 0 0 0 S 0.0 0.0 2579:17 rcuos/0
10 root 20 0 0 0 0 S 0.0 0.0 0:00.00 rcuob/0
11 root rt 0 0 0 0 S 0.0 0.0 4:37.08 migration/0
12 root rt 0 0 0 0 S 0.0 0.0 3:03.49 watchdog/0
## 通过上面的top命令可以看到pid为 8727、23525、24177的这3个服务CPU使用率很高，我们把服务名称过滤出来看是什么服务
$ ps -ef | egrep '8727|23525|24177'
root 8727 8705 99 May30 ? 1-16:21:16 /usr/java/latest/bin/java -javaagent:/alidata/agent/skywalking-agent.jar -Dskywalking.logging.output=CONSOLE -XX:-OmitStackTraceInFastThrow -Xms6144m -Xmx6144m -XX:MaxMetaspaceSize=512m -XX:MetaspaceSize=512m -XX:NewRatio=1 -XX:+DisableExplicitGC -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -Xloggc:/home/admin/logs/app/gc -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=20 -XX:GCLogFileSize=100m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/alidata/dump/order-10.233.34.130.hprof -Dapollo.meta=http://apollo-configserver:8080 -jar -Xms6144m -Xmx6144m -XX:-OmitStackTraceInFastThrow /alidata//app.jar --server.port=8080
root 23525 23505 99 May24 ? 10-21:22:09 /usr/java/latest/bin/java -javaagent:/alidata/agent/skywalking-agent.jar -XX:-OmitStackTraceInFastThrow -Xms4096m -Xmx4096m -XX:MaxMetaspaceSize=512m -XX:MetaspaceSize=512m -XX:NewRatio=1 -XX:+DisableExplicitGC -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -Xloggc:/home/admin/logs/app/gc -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=20 -XX:GCLogFileSize=100m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/alidata/dump/share-stock-10.233.34.132.hprof -Dapollo.meta=http://apollo-configserver:8080 -jar -Xms4096m -Xmx4096m -XX:-OmitStackTraceInFastThrow /alidata//app.jar --server.port=8080
root 24177 24155 98 May23 ? 8-09:16:26 /usr/java/latest/bin/java -javaagent:/alidata/agent/skywalking-agent.jar -XX:-OmitStackTraceInFastThrow -Xms2048m -Xmx2048m -XX:MaxMetaspaceSize=512m -XX:MetaspaceSize=512m -XX:NewRatio=1 -XX:+DisableExplicitGC -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -Xloggc:/home/admin/logs/app/gc -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=20 -XX:GCLogFileSize=100m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/alidata/dump/app-log-service-10.233.34.145.hprof -Dapollo.meta=http://apollo-configserver:8080 -Dapp.webapi.uri=http://app-webapi:8080 -jar -Xms2048m -Xmx2048m -XX:-OmitStackTraceInFastThrow /alidata//app.jar --server.port=8080
我们根据上面的命令可以看到占用大量CPU资源的是：order、share-stock、app-log-service，我们又观察了集群的其他节点，最终确认是order应用和share-stock应用占用了大量的CPU资源，这两个服务我们以前都反复的通过火焰图和抓包分析过很多次了，大量的CPU资源都是被连接kafka的相关操作消耗掉的，而我们跟开发沟通过，这两个服务本身就会依赖kafka，所以火焰图和网络包中会大量的出现kafka的身影不足为奇，基于以上情况我们建议：既然目前无法对order应用和share-stock应用进行性能优化，两个应用都是CPU资源的消耗大户，在集群中其他的节点计算资源还是充足的情况下，建议通过k8s的反亲和性，把这两个应用的pod分布在不同的节点来缓解CPU资源不足导致的性能问题。
3. 新增k8s反亲和性
我们把order和share-stock互相添加了反亲和性之后，看起来集群的CPU使用率和负载出现了小幅度下降，但是其中有一个节点的load飙升到了 30多，我们通过观察发现是应用share-stock和另一个应用，这里我们排除order应用，把占用CPU资源的应用确定为share-stock，原因很简单，我们只不过是使用了排除法。
$ top
top - 16:00:29 up 929 days, 23:34, 1 user, load average: 30.88, 23.51, 19.71
Tasks: 275 total, 1 running, 274 sleeping, 0 stopped, 0 zombie
%Cpu(s): 51.1 us, 9.5 sy, 0.0 ni, 35.8 id, 0.0 wa, 0.0 hi, 3.6 si, 0.0 st
KiB Mem : 65807708 total, 9119464 free, 40296088 used, 16392156 buff/cache
KiB Swap: 0 total, 0 free, 0 used. 24976800 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
4554 root 20 0 8968820 2.8g 12788 S 200.0 4.4 38:09.30 java
8775 root 20 0 11.0g 6.2g 12680 S 100.0 9.9 144:48.51 java
24995 root 20 0 9556116 3.0g 12816 S 87.5 4.7 110:40.35 java
13447 root 20 0 27.5g 602296 21188 S 37.5 0.9 4748:28 dotnet
14476 root 20 0 9259776 3.3g 11532 S 18.8 5.3 266:53.16 java
20893 root 20 0 9405132 3.1g 8736 S 12.5 5.0 132:31.63 java
27205 root 20 0 9688812 4.5g 6472 S 12.5 7.1 2760:43 java
6 root 20 0 0 0 0 S 6.2 0.0 28980:26 ksoftirqd/0
1276 root 20 0 5947728 968132 12372 S 6.2 1.5 73037:09 dockerd
2624 root 20 0 1645220 488280 7788 S 6.2 0.7 23151:22 ilogtail
4309 root 20 0 9985104 2.8g 11620 S 6.2 4.5 20:16.95 java
5427 root 20 0 8843076 1.6g 10828 S 6.2 2.5 89:17.40 java
6939 root 20 0 102416 51032 2336 S 6.2 0.1 390:18.01 gunicorn
6941 root 20 0 103560 52304 2336 S 6.2 0.1 390:48.98 gunicorn
6952 root 20 0 105872 54572 2340 S 6.2 0.1 423:19.17 gunicorn
7090 root 20 0 26.3g 1.4g 22288 S 6.2 2.3 810:06.10 dotnet
25528 root 20 0 162256 2184 1532 R 6.2 0.0 0:00.01 top
30951 root 20 0 26.4g 477824 49596 S 6.2 0.7 22:46.15 dotnet
1 root 20 0 44752 4012 1608 S 0.0 0.0 871:52.17 systemd
2 root 20 0 0 0 0 S 0.0 0.0 2:36.61 kthreadd
4 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/0:0H
7 root rt 0 0 0 0 S 0.0 0.0 5:44.53 migration/0
8 root 20 0 0 0 0 S 0.0 0.0 0:00.00 rcu_bh
9 root 20 0 0 0 0 S 0.0 0.0 5208:21 rcu_sched
10 root 0 -20 0 0 0 S 0.0 0.0 0:00.58 lru-add-drain
11 root rt 0 0 0 0 S 0.0 0.0 9:16.72 watchdog/0
## 我们过滤了4554发现是share-stock应用
$ ps -ef | grep 4554
[16:00:49:356]root 4554 4532 99 15:38 ? 00:38:42 /usr/java/latest/bin/java -javaagent:/alidata/agent/skywalking-agent.jar -XX:-OmitStackTraceInFastThrow -Xms4096m -Xmx4096m -XX:MaxMetaspaceSize=512m -XX:MetaspaceSize=512m -XX:NewRatio=1 -XX:+DisableExplicitGC -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -Xloggc:/home/admin/logs/app/gc -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=20 -XX:GCLogFileSize=100m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/alidata/dump/share-stock-10.233.50.12.hprof -Dapollo.meta=http://apollo-configserver:8080 -jar -Xms4096m -Xmx4096m -XX:-OmitStackTraceInFastThrow /alidata//app.jar --server.port=8080
既然种种迹象表明问题应用是share-stock，我们之前反复通过火焰图以及网络包都分析过了，但是我还是决定再次进行分析，不能因为之前分析过就放弃分析，可能之前遗漏了某些重要的信息。
4. 深入分析share-stock
由于火焰图我们已经看过好几次了，每次都是关于kafka的，我们这里就不看火焰图，我打算从网络层面入手进行分析。
$ nsenter -n -t 4554
$ timeout 60 tcpdump -i any -vvv -ttt -w share-stock-`date +%F`.pcap
tcpdump: listening on any, link-type LINUX_SLL (Linux cooked), capture size 262144 bytes
186185 packets captured
186213 packets received by filter
0 packets dropped by kernel
我们通过nsenter进入容器的网络命名空间，然后tcpdump抓取了1分钟时长的网络包。接下来我们使用tshark先分析一下。
$ tshark -q -z 'conv,tcp' -r share-stock-2023-05-31.pcap
================================================================================
TCP Conversations
Filter:<No Filter>
| <- | | -> | | Total | Relative | Duration |
| Frames Bytes | | Frames Bytes | | Frames Bytes | Start | |
10.233.50.12:51086 <-> 172.16.8.10:9092 6595 539 kB 6806 1,362 kB 13401 1,901 kB 0.000000000 59.9797
10.233.50.12:51072 <-> 172.16.8.10:9092 6579 538 kB 6775 1,358 kB 13354 1,897 kB 0.001246000 59.9775
10.233.50.12:51082 <-> 172.16.8.10:9092 6542 535 kB 6729 1,351 kB 13271 1,886 kB 0.001563000 59.9784
10.233.50.12:51080 <-> 172.16.8.10:9092 6534 534 kB 6735 1,622 kB 13269 2,157 kB 0.005175000 59.9692
10.233.50.12:51078 <-> 172.16.8.10:9092 6545 535 kB 6722 1,349 kB 13267 1,885 kB 0.005465000 59.9741
10.233.50.12:51074 <-> 172.16.8.10:9092 6496 531 kB 6667 1,351 kB 13163 1,883 kB 0.005969000 59.9674
10.233.50.12:51066 <-> 172.16.8.10:9092 6464 529 kB 6696 1,352 kB 13160 1,881 kB 0.005356000 59.9651
10.233.50.12:55186 <-> 172.16.8.9:9092 6494 531 kB 6655 1,510 kB 13149 2,042 kB 0.001450000 59.9725
10.233.50.12:51070 <-> 172.16.8.10:9092 6450 527 kB 6648 1,332 kB 13098 1,860 kB 0.001151000 59.9719
10.233.50.12:56898 <-> 172.16.8.11:9092 6207 509 kB 6419 1,486 kB 12626 1,996 kB 0.005444000 59.9734
10.233.50.12:51076 <-> 172.16.8.10:9092 5104 424 kB 5543 1,183 kB 10647 1,607 kB 0.001349000 59.9666
10.233.50.12:51084 <-> 172.16.8.10:9092 4264 352 kB 4650 981 kB 8914 1,334 kB 0.005519000 59.9748
10.233.50.12:38808 <-> 172.16.21.61:11800 1286 112 kB 1497 4,170 kB 2783 4,283 kB 0.082075000 59.5645
10.233.50.12:55532 <-> 172.16.9.159:3433 1554 527 kB 1051 192 kB 2605 720 kB 0.082779000 55.4061
172.16.8.11:9092 <-> 10.233.50.12:58698 714 81 kB 1540 1,681 kB 2254 1,762 kB 0.079761000 59.5390
10.233.50.12:53476 <-> 172.16.9.159:3433 1077 364 kB 723 147 kB 1800 511 kB 3.310134000 50.5215
172.16.8.9:9092 <-> 10.233.50.12:55270 527 57 kB 997 467 kB 1524 524 kB 0.280816000 59.2983
10.233.50.12:55860 <-> 172.16.9.159:3433 863 289 kB 574 93 kB 1437 383 kB 0.338880000 12.8890
10.233.50.12:44906 <-> 172.16.9.159:3433 670 226 kB 455 71 kB 1125 297 kB 2.788293000 34.8216
172.16.8.10:9092 <-> 10.233.50.12:51176 353 42 kB 743 213 kB 1096 256 kB 0.231980000 59.7390
10.233.50.12:55580 <-> 172.16.9.159:3433 518 168 kB 356 75 kB 874 243 kB 2.786426000 53.4755
172.16.8.9:9092 <-> 10.233.50.12:55230 238 26 kB 361 34 kB 599 60 kB 0.319861000 59.5267
172.16.8.10:9092 <-> 10.233.50.12:52826 239 27 kB 357 26 kB 596 53 kB 0.055464000 59.8522
172.16.8.10:9092 <-> 10.233.50.12:51166 239 25 kB 357 26 kB 596 52 kB 0.065342000 59.8105
172.16.8.10:9092 <-> 10.233.50.12:52814 239 25 kB 357 26 kB 596 52 kB 0.067596000 59.8245
172.16.8.10:9092 <-> 10.233.50.12:51110 239 25 kB 357 26 kB 596 52 kB 0.089756000 59.8179
10.233.50.12:51100 <-> 172.16.8.10:9092 355 26 kB 239 25 kB 594 52 kB 0.000313000 59.8684
172.16.8.9:9092 <-> 10.233.50.12:56988 237 25 kB 354 26 kB 591 51 kB 0.445724000 59.4887
172.16.8.10:9092 <-> 10.233.50.12:51104 236 25 kB 354 26 kB 590 51 kB 0.069600000 59.5398
172.16.8.10:9092 <-> 10.233.50.12:52864 236 25 kB 354 26 kB 590 51 kB 0.138227000 59.4686
172.16.8.10:9092 <-> 10.233.50.12:51106 236 26 kB 354 26 kB 590 52 kB 0.263707000 59.3428
172.16.8.10:9092 <-> 10.233.50.12:51094 236 25 kB 354 26 kB 590 51 kB 0.304210000 59.4115
172.16.8.11:9092 <-> 10.233.50.12:56926 234 24 kB 351 26 kB 585 51 kB 0.081723000 59.5122
10.233.50.12:36736 <-> 10.233.45.142:20880 227 287 kB 281 117 kB 508 404 kB 0.092263000 58.9260
10.233.50.12:47540 <-> 10.233.49.2:20880 200 325 kB 290 118 kB 490 444 kB 0.094341000 58.1117
10.233.50.12:41856 <-> 10.233.10.14:20880 194 272 kB 281 117 kB 475 390 kB 0.132810000 57.4128
这里我们可以明显看到应用是在和172.16.8.10的9092端口进行频繁的网络交互，9092就是kafka的服务端口，我们挑选了第一个TCP会话：10.233.50.12:51086 <-> 172.16.8.10:9092，这里我们通过跟踪TCP流发现：很多重复的看起来比较奇怪的网络包，如图1所示：
图1
我们通过wireshark的info段给出的信息可以得出这些网络包，全部都是heartbeat包，也就是我们平常所说的心跳检测，如图2所示：
图2
这里我们就怀疑是不是心跳检测的相关配置，设置的有问题，我们通过查询资料得出以下结论，应用连接kafka的心跳检测的配置项为：heartbeat.interval.ms，此单位为毫秒，而客户反馈他们的配置项是：spring.kafka.consumer.heartbeat-intervle=7，他们这里是需要进行转换的，因为他们配置的是7秒，而默认是毫秒，所以中间存在单位转换的代码，我们计算了一下一秒发生了80次以上的心跳检测，这里我们怀疑心跳检测的间隔是7ms，而不是我们之前认为的7s，开发经过检查发现：中间单位转换的代码是失败的，那么实际上确实是我们猜测的7ms。最终我们把此配置改为正常的7s之后，从监控图可以看到优化效果非常显著，load从平均每个节点 30左右，下降到了5左右，峰值从150下降到30左右。效果如图3所示：
图3