SLOWLOG là công cụ chẩn đoán hiệu năng tốt nhất của Redis. Bài này đo xem nó ghi gì, và quan trọng hơn — nó không ghi gì.
Một mục chứa gì
7 id
1788209014 dấu thời gian
289369 thời gian chạy, micro giây
eval "for i=1,300000 do ..." 0 lệnh và tham số
127.0.0.1:33296 địa chỉ khách
(trống) tên khách
Sáu trường, và hai trường cuối là thứ khiến SLOWLOG hữu ích hơn commandstats: nó cho biết ai gọi, không chỉ cái gì được gọi.
Mặc định:
slowlog-log-slower-than 10000 us (10 ms)
slowlog-max-len 128
Nó nằm hoàn toàn trong bộ nhớ và không ghi ra tệp — mất khi Redis khởi động lại.
Chỗ nó không ghi: lệnh phải xếp hàng
Đây là phép đo quan trọng nhất bài.
Tôi chạy một script EVAL mất 3.088.661 µs, và cùng lúc một khách khác gọi GET liên tục:
khách GET: n=784 | p50 0,124 ms | p99 1,861 ms | max 3.335,8 ms
Một lệnh GET mất 3,3 giây từ góc nhìn của khách.
Nhật ký lệnh chậm sau đó:
số mục: 1
id=8 3088661 us lệnh=EVAL
Chỉ có EVAL. Lệnh GET chờ 3,3 giây không xuất hiện ở đâu cả.
Vì sao, và nó nghĩa là gì
SLOWLOG đo thời gian chạy của lệnh, không đo thời gian nó nằm chờ trong hàng. GET đó chạy trong 0,1 ms như mọi GET khác — nó chỉ được chạy sau ba giây.
Hệ quả rất thực tế:
SLOWLOGcho biết ai gây ra nghẽn, không cho biết ai bị nghẽn.
Nếu người dùng báo "hệ thống chậm" và SLOWLOG trống, điều đó không có nghĩa Redis không phải thủ phạm. Hãy tìm một lệnh chậm bất kỳ trong đó và tính xem nó chặn bao nhiêu lệnh khác.
Để biết về phía nạn nhân, phải đo ở khách hàng — hoặc dùng redis-cli --latency, thứ đo đúng thời gian một PING mất từ đầu này sang đầu kia.
Hai công cụ trả lời hai câu hỏi, và cần cả hai.
Hai chỗ bị cắt
Số mục có trần.
slowlog-max-len 8, chạy 12 lệnh -> chỉ còn 8 mục, mục cũ bị vứt
Với mặc định 128, một đợt lệnh chậm ngắn có thể đẩy hết lịch sử cũ ra khỏi sổ. Đúng lúc bạn cần nhìn lại chuyện gì xảy ra trước đó thì nó đã bị ghi đè.
Nâng lên vài nghìn hầu như không tốn gì — mỗi mục chỉ vài trăm byte.
Tham số bị cắt.
MSET 34 tham số -> giữ 31, rồi "... (4 more arguments)"
tham số 300 byte -> giữ 128, rồi "... (172 more bytes)"
Hai giới hạn này không chỉnh được. Với lệnh nhiều khoá, bạn thấy 31 khoá đầu và biết còn bao nhiêu — thường đủ để nhận ra mẫu.
Đặt ngưỡng bao nhiêu
Mặc định 10 ms quá cao cho hệ thống nhạy độ trễ. Từ những gì đo trong sê-ri: một GET bình thường mất 0,06 µs xử lý, nên bất cứ thứ gì trên 1 ms đã là bất thường.
redis-cli config set slowlog-log-slower-than 1000 # 1 ms
redis-cli config set slowlog-max-len 1024
Đặt 0 ghi mọi lệnh — hữu ích trong vài giây để xem một quy trình cụ thể gọi gì, nhưng đừng để vậy: mỗi lệnh tốn thêm một lần ghi vào danh sách.
Đặt -1 tắt hẳn.
Đọc nó thế nào
redis-cli slowlog get 128 | paste - - - - - - - | \
awk '{printf "%8.1f ms %-12s %s\n", $3/1000, $4, $5}' | sort -rn | head -20
Ba câu hỏi cần trả lời khi nhìn danh sách:
Lệnh nào lặp lại nhiều nhất? Một KEYS chạy mỗi phút tệ hơn một KEYS chạy một lần.
Địa chỉ khách nào? Trường thứ sáu cho biết dịch vụ nào gọi. Với nhiều dịch vụ dùng chung một Redis, đây là cách duy nhất tìm ra thủ phạm.
Dấu thời gian có gom cụm không? Nhiều mục trong cùng vài giây nghĩa là một sự kiện, không phải vấn đề kéo dài — thường là một job định kỳ.
Đặt tên cho khách hàng
Trường "tên khách" mặc định trống, và đó là lãng phí. Mọi thư viện đều gửi được:
redis-cli client setname dich-vu-thanh-toan
Sau đó mỗi mục slowlog kèm tên dịch vụ thay vì một địa chỉ IP và cổng ngẫu nhiên. Với hệ thống nhiều dịch vụ, việc này biến SLOWLOG từ "có ai đó gọi KEYS" thành "dịch vụ báo cáo gọi KEYS".
Đây là một dòng cấu hình trong ứng dụng và nó tiết kiệm rất nhiều thời gian chẩn đoán về sau.
Kết hợp với các nguồn khác
Từ phần trước, bốn nguồn và vai trò của chúng:
| Nguồn | Trả lời |
|---|---|
SLOWLOG |
Lệnh cụ thể nào, tham số gì, ai gọi |
INFO commandstats |
Loại lệnh nào tiêu nhiều CPU nhất tổng cộng |
INFO latencystats |
Phân bố độ trễ theo loại lệnh |
redis-cli --latency |
Khách hàng thật sự chờ bao lâu |
Quy trình chẩn đoán hiệu quả: --latency để xác nhận có vấn đề, commandstats để biết loại lệnh, SLOWLOG để biết chính xác lệnh nào và ai gọi.
Thử ba mươi giây
Bật chi tiết hơn và xem trong một phút:
redis-cli config set slowlog-log-slower-than 1000
redis-cli config set slowlog-max-len 1024
redis-cli slowlog reset
sleep 60
redis-cli slowlog get 1024 | paste - - - - - - - | \
awk '{printf "%8.1f ms %-14s %-20s %s\n", $3/1000, $4, $6, $5}' | sort -rn | head -20
Rồi đối chiếu với phía khách:
redis-cli --latency-history -i 10
Nếu --latency cho thấy đỉnh hàng trăm mili giây mà SLOWLOG không có mục nào tương ứng về thời điểm, thủ phạm nằm ngoài lệnh Redis — thường là fork khi lưu RDB (phần 18), hoặc bộ nhớ tráo đổi. Cả hai đều làm cả tiến trình đứng lại mà không có lệnh nào bị tính là chậm.
Phần sau: đo và tối ưu bộ nhớ — quy trình đầy đủ từ chỉ số tới hành động.
