怪兽和他的朋友们

Monster

0%

记一次 k8s Pod 不稳定排错，从头到尾花了半天

发表于 分类于
本文字数： 4.5k 阅读时长 ≈ 4 分钟

一、前言

某个周四下午，线上反馈说某个微服务的接口时不时返回 502。看了一眼监控面板——Pod 在频繁重启，一个小时内重启了 8 次。登录 Kibana 一看日志，啥都没有，Pod 挂了日志还没来得及刷盘。

这种"时好时坏、没有日志"的故障最烦人。本文把这次排错的完整过程记录下来，从现象到根因，每一步做什么、为什么这么做，都写清楚。

二、现象

2.1 第一眼

1
2
3
4
5
6
# 查看 Pod 状态
kubectl get pods -n production

NAME                          READY   STATUS    RESTARTS      AGE
api-service-7d4f8c6b9-2kx9j   0/1     Running   8 (2m ago)    45m
api-service-7d4f8c6b9-ht3ws   1/1     Running   2 (15m ago)   2d

两个副本，一个有 8 次重启，一个只有 2 次。健康的那个重启 2 次也是异常的（正常情况应该是 0）。

1
kubectl describe pod api-service-7d4f8c6b9-2kx9j -n production

重点看 Last State 部分：

1
2
3
4
5
6
7
8
Containers:
  api:
    State:          Running (started 2 minutes ago)
    Last State:     Terminated
      Reason:       OOMKilled
      Exit Code:    137
    Ready:          False
    Restart Count:  8

OOMKilled + Exit Code 137，明确的信号——进程被 cgroup OOM Killer 干掉了。

2.2 第一反应

看到 OOMKilled，本能反应就是"内存 limit 设小了"。查了一下 Deployment 的资源限制：

1
2
3
4
5
6
7
resources:
  limits:
    cpu: "1"
    memory: "512Mi"
  requests:
    cpu: "0.5"
    memory: "256Mi"

512Mi 的 limit。看了下正常运行的 Pod 的内存占用：

1
2
3
4
kubectl top pod api-service-7d4f8c6b9-ht3ws -n production

NAME                          CPU(cores)   MEMORY(bytes)
api-service-7d4f8c6b9-ht3ws  120m         487Mi

内存已经 487Mi，接近 512Mi 的 limit 了。这个副本还在运行但离上限只有 25Mi 的余量。另一个副本可能因为流量分布不均刚好触到了 OOM。

第一轮修复：把 memory limit 从 512Mi 加到 1024Mi，request 也提到 512Mi。等待观察。

三、加完 limit 没解决

3.1 仍然重启

加完资源半小时后，重启次数还在涨：

1
kubectl get pods -n production -w

新 Pod 上线后还是会挂，只是间隔时间拉长了一些。

3.2 看事件

1
kubectl get events -n production --sort-by='.lastTimestamp' | tail -20
1
2
3
40m        Warning   BackOff              pod/api-service-7d4f8c6b9-2kx9j    Back-off restarting failed container
38m        Warning   Unhealthy            pod/api-service-7d4f8c6b9-2kx9j    Readiness probe failed: HTTP probe failed with statuscode: 503
35m        Warning   Unhealthy            pod/api-service-7d4f8c6b9-ht3ws    Liveness probe failed: HTTP probe failed with statuscode: 502

Readiness probe 和 Liveness probe 都在报错。这说明容器虽然没被 OOM Kill，但已经无法正常响应请求了。等到探针连续失败几次，kubelet 就会重启容器。

3.3 查 Java 进程内部

这个服务是 Java 写的，看了一眼启动参数：

1
2
# 容器启动命令
java -jar app.jar -Xmx512m -Xms512m

-Xmx512m 限制了 JVM 堆最大 512MB。但容器 limit 已经加到 1024Mi 了，这里只用了 512Mi，说明不是堆的问题。

问题在堆外内存（Off-Heap Memory）：NIO Direct Buffer、Metaspace、线程栈、JNI 开销等等。Java 的 -Xmx 只管堆，堆外内存它不管。

1
2
3
4
5
6
7
8
9
# 进到 Pod 里看看
kubectl exec -it api-service-7d4f8c6b9-ht3ws -n production -- /bin/bash

# 看进程内存
cat /proc/1/status | grep -E "VmRSS|VmSize|VmPeak"

VmPeak:	 1350 MB    # 进程历史上最高用到 1.35GB
VmSize:	  980 MB    # 当前虚拟内存
VmRSS:	  812 MB    # 当前物理内存 812MB  (limit 1024Mi)

VmRSS 812MB，容器 limit 1024Mi，看起来还有余量，但为什么不稳定？

3.4 看 GC 日志

找运维把 GC 日志拉出来：

1
2
3
4
5
6
7
8
2024-04-18T14:23:11.123+0800: [GC (Allocation Failure) ...
  2024-04-18T14:23:11.125+0800: [Full GC (Ergonomics) ...
     [PSYoungGen: 1536K->0K(2048K)] [ParOldGen: 349M->348M(512M)]
      349M(512M)  [Metaspace: 89M->89M(512M)]

2024-04-18T14:23:12.001+0800: [GC (Allocation Failure) ...
  2024-04-18T14:23:12.003+0800: [Full GC (Ergonomics) ...
     [PSYoungGen: 1536K->0K(2048K)] [ParOldGen: 348M->347M(512M)]

Full GC 几乎每秒触发一次，老年代几乎填满无法回收。这不是正常状态。

四、根因

4.1 抓线程 dump

1
2
kubectl exec -it api-service-7d4f8c6b9-ht3ws -n production -- \
  jstack 1 > /tmp/threaddump.txt

分析 dump 文件发现大量线程卡在同一个地方：

1
2
3
4
"http-nio-8080-exec-172" #172 daemon prio=5 os_prio=0 tid=0x00007f...
    java.lang.Thread.State: BLOCKED
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:160)
    - waiting to lock <0x0000000780a8b1a0> (a com.zaxxer.hikari.pool.HikariPool)

大量 HTTP 线程都在等数据库连接。HikariCP 连接池满了，所有请求都在排队。

4.2 查数据库侧

连接池配置：

1
2
3
4
5
spring:
  datasource:
    hikari:
      maximum-pool-size: 20
      connection-timeout: 30000

20 个连接，30 秒超时。一旦某个慢查询把连接占住不放，后面的请求就全部阻塞。

翻数据库的 processlist：

1
SELECT * FROM information_schema.PROCESSLIST WHERE COMMAND != 'Sleep' ORDER BY TIME DESC;

发现一条 SQL 跑了 37 秒：

1
SELECT * FROM order_detail WHERE order_no IN ('...', '...', ...)

order_no 没有索引，IN 子句里传了 500 多个值，每次查询走全表扫描。这张表 200 万行，平均每次扫描耗时 20-30 秒。

4.3 完整链路

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
慢查询 (30s+)
    ↓
20 个连接被占满（慢查询 + 等待的请求）
    ↓
新请求拿不到连接，HikariCP 线程阻塞
    ↓
Tomcat 线程池也满了，HTTP 请求堆积
    ↓
请求堆积 → 堆外内存暴涨（线程栈）
    ↓
容器内存超过 limit → OOMKilled
    ↓
kubelet 重启容器
    ↓
重启后旧连接释放，恢复正常
    ↓
过几分钟慢查询又触发 → 循环

五、修复

5.1 紧急止血

临时加索引，先让慢查询停下来：

1
ALTER TABLE order_detail ADD INDEX idx_order_no (order_no);

加完索引后，那条 SQL 从 30 秒降到 2 毫秒。连接池不再被占满，Pod 重启立即停止。

5.2 后续改进

问题 修复
order_no 无索引 已加索引，并纳入 DDL Review 流程
HikariCP 没有连接超时检测 加 max-lifetime: 600000，超时连接强制回收
慢查询无告警 开启 MySQL slow_query_log，超过 1 秒的 SQL 推送钉钉
容器内存余量不足 调大 limit 到 2048Mi，JVM -Xmx 保持 512Mi，留足堆外内存
监控盲区 接入 Pod 重启事件告警 + GC 耗时监控

5.3 一个有用的配置

HikariCP 加这个参数可以检测慢连接：

1
2
3
4
5
6
spring:
  datasource:
    hikari:
      connection-test-query: SELECT 1
      validation-timeout: 3000
      leak-detection-threshold: 60000  # 连接占用超过 60 秒打印告警日志

leak-detection-threshold 不会杀死连接，但会在日志里打印出栈信息——下次定位问题就不用 dump 线程了。

六、总结

排查步骤 用的命令/工具 发现了什么
看 Pod 状态 kubectl get pods 频繁重启
看容器退出原因 kubectl describe pod OOMKilled, Exit 137
看内存占用 kubectl top pod, /proc/status RSS 接近 limit
看 GC 日志 -XX:+PrintGCDetails 连续 Full GC
线程 dump jstack 卡在 HikariCP 拿连接
数据库 processlist SHOW PROCESSLIST 慢查询无索引
加索引 ALTER TABLE ... ADD INDEX 问题解决

回过头看，这次排错花了半天，但真正的根因其实很简单——一张表的字段没加索引。OOMKilled 只是表面现象，慢查询占满连接池导致线程堆积才是真凶。

这次之后我养成一个习惯：线上 Java 服务出 OOM，第一反应不是加内存 limit，而是先看线程 dump。内存不够往往是结果，不是原因。