PHP-FPM treo khi không có traffic: strace, ss và slowlog

Có một kiểu sự cố làm người vận hành bối rối: balancer trả 502/504 từng đợt, lưu lượng gần như bằng không, vậy mà pool PHP-FPM lúc nào cũng đầy worker. Đó là PHP-FPM treo vì chờ, không phải vì quá tải. Bài này mô tả một tình huống điển hình trên Cloud VPS và quy trình lần ra nguyên nhân theo đúng thứ tự: từ ps tới strace, /proc, ss, log Laravel, và chỗ mà slowlog lẽ ra phải có mặt ngay từ đầu.

Triệu chứng

Balancer trả 502/504 từng đợt cho một site, không theo giờ cao điểm. Mỗi đợt là một lần PHP-FPM treo trên các minion chạy site đó.
Pool luôn bận 100%, không có worker rảnh, trong khi lưu lượng lúc kiểm tra gần bằng không.

Log PHP-FPM lặp lại cảnh báo:

WARNING: [pool www] server reached pm.max_children setting (15)

CPU minion không cao. Đây là dấu hiệu đầu tiên cho thấy PHP-FPM treo vì chờ chứ không phải vì tính toán.

Điều tra PHP-FPM treo theo đúng thứ tự

Loại bỏ giả thuyết sai

Một giả thuyết hay gặp: "request đã dừng nhưng worker vẫn bị giữ, có thể do thread nền". Đây là hướng sai: mỗi worker PHP-FPM xử lý tuần tự từng request trên một tiến trình, không có thread nền nào giữ worker sau khi request kết thúc. Nếu worker còn bận thì request vẫn đang chạy, chỉ là phía client đã bỏ đi. Câu hỏi đúng khi gặp PHP-FPM treo là: worker đang làm gì?

ETIME lớn, TIME nhỏ: dấu hiệu PHP-FPM treo vì chờ

ps -eo pid,etime,time,pcpu,stat,cmd | grep 'php-fpm: pool www' | grep -v grep

ETIME là thời gian thực kể từ khi tiến trình bắt đầu xử lý, TIME là thời gian CPU nó đã dùng. Worker sống hàng chục phút mà chỉ đốt vài chục giây CPU nghĩa là phần lớn thời gian nằm chờ. Một worker PHP-FPM treo kiểu này thường chờ một trong ba thứ: database, file, hoặc mạng.

strace: worker chờ trên file descriptor nào

Gắn strace vào một worker đang chạy lâu:

strace -p <PID>

recvfrom(11, ..., 1, MSG_PEEK, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
sendto(11, "\27\3\3\3 \f^\242..."..., 805, MSG_NOSIGNAL, NULL, 0) = 805
poll([{fd=11, events=POLLIN}], 1, 1000) = 1 ([{fd=11, revents=POLLIN}])
recvfrom(11, "\27\3\3\2\244", 5, 0, NULL, NULL) = 5
recvfrom(11, "n\332\301\303..."..., 676, 0, NULL, NULL) = 676

Ba byte đầu \27\3\3 (0x17 0x03 0x03) là phần đầu của bản ghi TLS loại application data: worker đang nói chuyện HTTPS. Mẫu lặp gửi vài trăm byte, poll chờ, nhận về vài trăm byte, rồi lại gửi tiếp là hình dạng của rất nhiều request HTTP nhỏ, tuần tự, trên cùng một kết nối keep-alive.

/proc và ss: file descriptor đi đâu

ls -l /proc/<PID>/fd/11
# ... -> 'socket:[...]'

ss -apn | grep "pid=<PID>,"
# tcp ESTAB ... 10.0.0.102:35806  <IP-storage>:8443  users:(("php-fpm",pid=...,fd=11))

# bao nhiêu worker đang giữ kết nối tới cùng đích
ss -apn | grep ':8443' | grep php-fpm | wc -l

Nếu đích là object storage tương thích S3 nơi site lưu ảnh, và phần lớn worker đang giữ socket tới đúng địa chỉ đó, thì gần như toàn bộ pool PHP-FPM treo trên một dịch vụ bên ngoài duy nhất.

Tìm ai mở kết nối: log ứng dụng thường nhanh hơn grep code

grep -rn "8443" trong thư mục site thường không ra gì, vì cổng đến từ cấu hình endpoint của S3 client. Log Laravel trả lời thay, nếu ứng dụng có log lỗi kèm stack trace:

production.ERROR: Error in checkOrCreateInBucket
  {"error":"Error executing \"ListObjectsV2\" on \"https://<storage-endpoint>:8443/...\";
   AWS HTTP error: cURL error 6: Could not resolve host: <storage-endpoint> ..."}
#20 .../Middleware/ImageDomainMiddleware.php(132): checkOrCreateInBucket(...)

Trong tình huống này, thủ phạm là một middleware thay domain ảnh, gắn vào group web, gọi API ListObjectsV2 để kiểm tra từng ảnh đã có trên bucket chưa. Cấu hình package cho thấy việc kiểm tra chạy đồng bộ ngay trong request:

// config/image-domain.php
'queue_bucket_check' => false, // true thì đẩy việc kiểm tra/tạo ảnh vào queue

Vì sao max_execution_time không cắt được request

Trong trace thường thấy dòng:

setitimer(ITIMER_PROF, {..., it_value={tv_sec=60, tv_usec=0}}, NULL) = 0

ITIMER_PROF là cách PHP cài max_execution_time trên Linux, bộ đếm này đo thời gian CPU chứ không đo thời gian thực. Tài liệu set_time_limit của PHP nói rõ thời gian chờ stream, truy vấn database hay lời gọi hệ thống không được tính. Một request chờ mạng hàng chục phút vẫn chưa "chạm" giới hạn 60 giây. Đây là lý do PHP-FPM treo lâu đến vậy mà không bị PHP tự cắt.

Đọc code: vì sao một ảnh thành nhiều lời gọi mạng

Với mỗi URL ảnh, hàm kiểm tra gọi exists() cho ảnh gốc, bản webp, bản resize; thiếu bản nào thì tải ảnh về rồi upload. Ước lượng ví dụ: trang có 100 ảnh × 5 lời gọi × 2 giây là khoảng 1.000 giây cho một request. Có hai đường kích hoạt hay gặp:

AJAX trả JSON: middleware duyệt toàn bộ JSON, gặp chuỗi nào là URL ảnh thì kiểm tra. Response nhiều URL ảnh là nhiều lần gọi S3 trong cùng một worker.
Script fallback: middleware chèn một script vào trang; ảnh nào lỗi thì trình duyệt gọi endpoint lấy ảnh thay thế, endpoint này lại kiểm tra S3. Trang có vài chục ảnh lỗi là vài chục request song song, đủ lấp đầy một pool nhỏ.

Slowlog: mảnh còn thiếu

Với PHP-FPM treo, strace cho biết worker chờ trên socket nào, nhưng không cho biết dòng PHP nào đang chờ. Nếu ứng dụng không log lỗi, cách nhanh nhất để thấy dòng code là slowlog: request chạy quá ngưỡng thì FPM in backtrace PHP của request đó ra file. Nên bật sẵn cho mọi pool:

; pool www
request_slowlog_timeout = 5s
slowlog = /var/log/php-fpm/www-slow.log
request_terminate_timeout = 60s

Theo tài liệu cấu hình PHP-FPM, request_terminate_timeout tính theo thời gian thực, nên nó cắt được request chờ mạng mà max_execution_time bỏ qua.

Nguyên nhân gốc

Bốn yếu tố cộng lại thành sự cố PHP-FPM treo:

Middleware gọi object storage đồng bộ trong vòng đời request, mỗi ảnh nhiều lượt, không cache kết quả exists().
S3 client không đặt timeout. Khi phía storage chậm hoặc lỗi DNS, worker chờ tới khi từng lời gọi tự kết thúc.
Pool nhỏ dùng chung (ví dụ pm.max_children = 15): chỉ cần chừng ấy request chậm là cạn.
max_execution_time không tính thời gian chờ mạng, và không có giới hạn thời gian thực nào ở FPM.

Khắc phục PHP-FPM treo

Tạm thời

Restart PHP-FPM trả site về trong vài phút, nhưng PHP-FPM treo trở lại ngay khi trang nhiều ảnh được gọi. Không nên tăng pm.max_children: thêm worker là thêm kết nối song song tới storage đang chậm, làm nó chậm hơn nữa.

Chuyển việc kiểm tra ảnh sang queue và kiểm chứng

cd /var/www/example.com
# 1. config/image-domain.php: 'queue_bucket_check' => true
php artisan config:clear                 # 2
supervisorctl status                     # 3. queue worker phải RUNNING
systemctl restart php8.2-fpm             # 4. giải phóng worker đang kẹt

# kiểm chứng
ss -apn | grep ':8443' | grep php-fpm | wc -l
curl -o /dev/null -s -w "time=%{time_total}s code=%{http_code}\n" https://example.com/

Làm đủ trên mọi minion chạy site. Một lỗi hay gặp: sửa tay file cấu hình trên server, rồi lần deploy sau ghi đè lại giá trị cũ, và PHP-FPM treo quay lại y như trước. Giá trị quan trọng phải nằm trong repo hoặc .env có kiểm soát.

Lâu dài

Cache kết quả exists() vào Redis, để một ảnh chỉ bị kiểm tra một lần trong khoảng thời gian dài.
Đặt connect_timeout khoảng 3 giây và timeout khoảng 5 giây cho S3 client.
Bỏ hẳn lời gọi đồng bộ khỏi middleware; mọi việc kiểm tra và tạo ảnh đi qua queue.

Phòng ngừa PHP-FPM treo

Bảng nhận diện nhanh PHP-FPM treo:

Dấu hiệu	Ý nghĩa	Lệnh
Pool đầy nhưng traffic thấp	Request chậm, không phải bị dội tải	`grep max_children /var/log/php*-fpm.log`
ETIME lớn, TIME nhỏ	Worker chờ I/O	`ps -eo pid,etime,time,cmd`
Nhiều kết nối ra một IP ngoài	Gọi dịch vụ bên ngoài trong request	`ss -apn \| grep php-fpm`
`poll` lặp trên một fd	Chuỗi lời gọi mạng tuần tự	`strace -p <PID>`
Cần biết dòng code	Backtrace PHP của request chậm	`request_slowlog_timeout`

Thêm vào checklist review code: mọi lời gọi HTTP ra ngoài trong request phải có timeout ngắn, và không package nào được gọi mạng trong middleware toàn cục. Restart PHP-FPM định kỳ như cơ chế trong bài Self-healing tiết kiệm: tự phát hiện và khởi động lại dịch vụ chết chỉ che loại lỗi này: pool sạch vài giờ rồi PHP-FPM treo lại. Cách đọc log balancer khi sự cố lan rộng có ở bài OOM nginx trên balancer: khi một máy nhỏ gánh nhiều website.

Bài học

Pool đầy không có nghĩa là tải cao. Khi nghi PHP-FPM treo, so ETIME với TIME trước khi nghĩ tới chuyện tăng worker.
strace trả lời "đang chờ cái gì", slowlog trả lời "dòng code nào". Cần cả hai; bật slowlog trước khi sự cố xảy ra.
max_execution_time không bảo vệ khỏi chờ mạng. Giới hạn thời gian thực phải đặt ở FPM và ở từng HTTP client.
Sửa tay trên server không bền. Cấu hình phải đi qua repo và quy trình deploy.
Đếm lại số liệu gốc trước khi viết báo cáo. Con số ước lượng nhanh từ trace thường lệch; kết luận có thể không đổi, nhưng độ tin cậy thì có.

Bài tiếp theo

TTFB cao với Googlebot: tách từng chặng và nghi vấn scraper nội bộ. Khi bot của Google thấy site chậm hơn người dùng thật, và lý do có thể nằm ngay trong hạ tầng của chính mình.

PHP-FPM treo: lần theo strace tới cuộc gọi S3 đồng bộ