Gỡ lỗi khi máy chậm

Bốn mươi tám phần trước đo từng thứ riêng lẻ. Bài này dựng một sự cố thật rồi đi tìm nguyên nhân, dùng đúng những công cụ đó.

Sự cố

Một dịch vụ xử lý yêu cầu, mỗi yêu cầu tốn khoảng 15 ms CPU. Nó chậm.

p50  95,19 ms  |  p95 179,87 ms  |  p99 183,30 ms

Bản khoẻ mạnh của cùng dịch vụ đó, cùng máy:

p50  16,97 ms  |  p95  17,67 ms  |  p99  18,43 ms

Chậm gấp mười lần ở đuôi. Không có lỗi trong nhật ký, không có ngoại lệ, không có gì thay đổi trong mã nguồn.

Bước 1 — Nhìn cái ai cũng nhìn

docker stats --no-stream suco

suco: CPU 100.87%  |  MEM 936KiB / 15.6GiB (0.01%)

CPU đầy, bộ nhớ trống trơn. Kết luận tự nhiên: "hết CPU rồi, cấp thêm nhân."

Kết luận đó sai, và cấp thêm nhân cho tiến trình này không giúp gì. Lý do nằm ở bước hai.

Bước 2 — Nhìn cái gần như không ai nhìn

docker exec suco cat /sys/fs/cgroup/cpu.stat

Đọc hai lần cách nhau mười giây và lấy hiệu:

100 chu kỳ, bị ghim 100 lần = 100,0%
cpu.max: 100000 100000     nproc báo: 16

Bị ghim 100% số chu kỳ.

Đây là dấu vết quyết định. Nó nói rằng mỗi chu kỳ 100 ms đều chạm trần quota, và mọi luồng đang chạy bị treo cho tới chu kỳ sau. Phần 35 đã đo chính xác hiện tượng này.

Dòng thứ hai giải thích vì sao ứng dụng lại rơi vào tình trạng đó: cpu.max cho một nhân, còn nproc báo 16. Ứng dụng — hoặc runtime của nó — tự chọn kích thước theo nproc.

Con số 100,87% ở bước 1 không phải "CPU đầy". Nó là "đã dùng hết quota". Hai chuyện khác nhau, và chỉ một trong hai chữa được bằng cách cấp thêm nhân.

Bước 3 — Đếm luồng

docker exec suco sh -c 'ls /proc/1/task | wc -l'

9

Chín luồng tranh nhau một nhân. Khớp với nproc báo 16 ở bước trước.

Bước 4 — Loại trừ ba tài nguyên còn lại

docker exec suco sh -c 'cat /proc/pressure/cpu /proc/pressure/io'

cpu  some avg10=50.75  avg60=18.72  avg300=10.38
cpu  full avg10=0.00
io   some avg10=0.00   avg60=0.04   avg300=0.07
io   full avg10=0.00

cpu some avg10=50.75 — một nửa thời gian có ít nhất một luồng bị đình trệ chờ CPU.

io some avg10=0.00 — không có gì chờ ổ đĩa. Giả thuyết "chậm vì đĩa" bị loại bỏ dứt điểm, bằng một lệnh cat.

PSI (/proc/pressure/*) là chỉ số chẩn đoán tốt nhất mà phần lớn hệ thống giám sát không thu thập. Nó trả lời trực tiếp câu hỏi "tiến trình đang chờ cái gì", thay vì "tài nguyên nào đang bận".

Chữa và đo lại

Giảm số luồng xuống một, đúng bằng quota:

p50  16,97 ms  |  p95 17,67 ms  |  p99 18,43 ms

p99 từ 183,30 ms về 18,43 ms. Mười lần, không đổi một dòng logic nào, không cấp thêm tài nguyên nào.

Thứ tự đúng: loại trừ theo tài nguyên

Sai lầm phổ biến nhất khi gỡ là đoán theo kinh nghiệm — mở mã nguồn, tìm chỗ nghi ngờ, thử sửa. Cách hiệu quả hơn là loại trừ bốn tài nguyên trước khi mở mã nguồn, và ba trong bốn trả lời được bằng một lệnh cat.

Ba mẹo đọc từng bước:

CPU — nr_throttled / nr_periods trên 5% là đã ảnh hưởng tới đuôi. Con số phần trăm CPU không phát hiện được việc bị ghim; phần 35 đã đo trường hợp CPU chỉ 62,6% mà p99 đã là 113 ms.

Bộ nhớ — nhìn anon, không nhìn memory.current. Phần 34 cho thấy một container ghi tệp 400 MB hiện 81% giới hạn trong khi ứng dụng giữ 0 MB.

Ổ đĩa — pressure/io full khác 0 nghĩa là mọi tiến trình đều đang chờ đĩa. Đó là tín hiệu mạnh hơn nhiều so với %util của iostat, vốn bão hoà ở 100% từ rất sớm trên NVMe.

Một sự cố tôi dựng mà không tái hiện được

Tôi định dựng sự cố thứ hai: ghi log có fsync mỗi dòng — thứ phần 41 đo là đắt gấp 11.464 lần so với ghi có bộ đệm.

1 luồng, không fsync : p50 16,97 ms | p99 18,43 ms
1 luồng, CÓ fsync    : p50 17,44 ms | p99 19,24 ms

Gần như không khác gì.

Lý do: ở tần suất khoảng 50 yêu cầu mỗi giây, một fsync 516 µs cho mỗi yêu cầu chỉ chiếm 2,6% thời gian. Cái giá có thật, nó chỉ chưa đủ lớn để nhìn thấy.

Đây là bài học đáng giá ngang với sự cố chính: một thực hành xấu có thể vô hình ở tải thấp và trở thành sự cố ở tải cao. Nếu tôi tăng tải lên 500 yêu cầu mỗi giây, cùng đoạn mã đó sẽ chiếm 26% và bắt đầu lộ ra.

Nên khi gỡ lỗi, câu hỏi "cái này có tệ không" ít hữu ích hơn câu hỏi "cái này chiếm bao nhiêu phần trăm của ngân sách thời gian".

Thử ba mươi giây

Chạy nguyên bộ bốn bước trên một container đang phục vụ thật:

c=<ten-container>
echo "=== 1. CPU day hay bi ghim? ==="
docker stats --no-stream --format '{{.Name}}: CPU {{.CPUPerc}} MEM {{.MemPerc}}' $c
docker exec $c sh -c '
  p1=$(awk "/nr_periods/{print \$2}" /sys/fs/cgroup/cpu.stat)
  t1=$(awk "/nr_throttled/{print \$2}" /sys/fs/cgroup/cpu.stat)
  sleep 10
  p2=$(awk "/nr_periods/{print \$2}" /sys/fs/cgroup/cpu.stat)
  t2=$(awk "/nr_throttled/{print \$2}" /sys/fs/cgroup/cpu.stat)
  awk -v p=$((p2-p1)) -v t=$((t2-t1)) "BEGIN{if(p>0)printf \"  ghim %.1f%% chu ky\n\",t*100/p}"
  echo "  cpu.max=$(cat /sys/fs/cgroup/cpu.max)  nproc=$(nproc)  luong=$(ls /proc/1/task|wc -l)"'

echo "=== 2. Bo nho that ==="
docker exec $c sh -c 'awk "/^anon |^file /{printf \"  %-6s %d MB\n\",\$1,\$2/1048576}" /sys/fs/cgroup/memory.stat
  grep . /sys/fs/cgroup/memory.events | tr "\n" " "; echo'

echo "=== 3+4. Dang cho cai gi ==="
docker exec $c sh -c 'for f in cpu io memory; do
  printf "  %-7s %s\n" "$f" "$(grep ^some /proc/pressure/$f 2>/dev/null)"; done'

Đọc kết quả theo đúng thứ tự đó. Dòng nào có some avg10 lớn chỉ thẳng vào tài nguyên đang thiếu — và nếu cả ba đều gần 0 trong khi dịch vụ vẫn chậm, lúc đó mới đến lượt perf và biểu đồ ngọn lửa.

Phần sau: danh sách kiểm và chốt sê-ri — gom mọi phép đo của năm mươi phần.