strace là công cụ tôi đã dùng ở phần 25 để đếm lời gọi hệ thống. Bài này đo xem việc dùng nó tốn bao nhiêu — và câu trả lời giải thích vì sao không bao giờ được gắn nó vào một dịch vụ đang phục vụ.
Bảng
Chương trình gọi write() 300.000 lần vào /dev/null:
| Cách theo dõi | Tổng thời gian | µs mỗi lời gọi | Chậm hơn |
|---|---|---|---|
| Không theo dõi gì | 0,034 s | 0,11 | 1× |
perf stat -e raw_syscalls:sys_enter |
0,045 s | 0,15 | 1,4× |
perf trace |
2,812 s | 9,37 | 85× |
strace -c (chỉ đếm) |
14,718 s | 49,06 | 446× |
strace -e trace=write → /dev/null |
15,551 s | 51,84 | 471× |
strace đầy đủ, ghi ra tệp |
16,526 s | 55,09 | 501× |
-c không giúp gì
Đây là điều bất ngờ nhất. strace -c chỉ đếm và in một bảng tổng hợp ở cuối — nó không in một dòng nào trong lúc chạy. Trực giác nói nó phải rẻ hơn nhiều.
Nó chậm 446 lần, so với 501 lần của bản in đầy đủ ra tệp. Chênh nhau 12%.
Lý do: cái giá không nằm ở việc in ra. Nó nằm ở ptrace.
Mỗi lời gọi hệ thống của tiến trình bị theo dõi phải dừng lại hai lần — một lần khi vào nhân, một lần khi ra — và mỗi lần dừng là một chuyển ngữ cảnh sang tiến trình strace, một lượt đọc thanh ghi qua ptrace, rồi một chuyển ngữ cảnh quay lại.
Bốn lần chuyển ngữ cảnh cho một lời gọi vốn chỉ tốn 0,11 µs. Phần 5 đã đo chuyển ngữ cảnh qua nhân khác tốn 12,4 µs; nhân bốn là ra đúng bậc độ lớn của con số 49 µs ở đây.
Nói lại lần thứ hai: mọi cờ của strace đều tốn như nhau. Chọn -c để "nhẹ hơn" là hiểu sai chỗ tiền đi.
Nhưng trên chương trình không gọi hệ thống thì nó miễn phí
Vòng lặp tính toán thuần, 300 triệu vòng, gần như không có lời gọi hệ thống nào:
không theo dõi : 0,393 s
strace -c : 0,390 s
Không đo được khác biệt.
Đây là điều quan trọng để dùng công cụ cho đúng: chi phí của strace tính theo số lời gọi hệ thống, không tính theo thời gian chạy.
- Chương trình gọi một triệu lần mỗi giây: chậm 450 lần, không dùng được.
- Chương trình gọi một trăm lần mỗi giây: thêm 5 ms mỗi giây, không ai thấy.
Trước khi gắn strace, hãy ước lượng tần suất gọi. perf stat -e raw_syscalls:sys_enter -p <pid> -- sleep 5 cho con số đó trong 5 giây với chi phí gần bằng 0.
Đếm mà không làm chậm
perf stat -e raw_syscalls:sys_enter -p <pid> -- sleep 10
Trong phép đo của tôi, lệnh này đếm được 300.033 lời gọi — đúng con số thật cộng phần khởi động — và chỉ làm chậm 1,4 lần.
Nó dùng tracepoint của nhân: nhân tự tăng một bộ đếm, không có tiến trình nào bị dừng. Đó là khác biệt cơ bản với ptrace.
Muốn biết loại lời gọi nào chiếm nhiều nhất mà vẫn rẻ:
perf stat -e 'syscalls:sys_enter_*' -p <pid> -- sleep 5 2>&1 | sort -k1 -n -r | head -10
Và với eBPF (nếu có bcc-tools hoặc bpftrace):
syscount -p <pid> -d 10 # dem theo loai, chi phi rat thap
funclatency -p <pid> 'do_sys_open*'
eBPF chạy trong nhân và không dừng tiến trình, nên chi phí gần với perf stat chứ không gần với strace.
Vậy strace dùng khi nào
strace vẫn là công cụ tốt nhất cho các câu hỏi định tính, nơi một lần chạy chậm cũng không sao:
Chương trình tìm tệp cấu hình ở đâu:
strace -f -e trace=openat,stat,access ./chuong-trinh 2>&1 | grep -v ENOENT
Vì sao nó trả về lỗi:
strace -f -e trace=%file ./chuong-trinh 2>&1 | grep -E 'E[A-Z]+ '
Nó đang treo ở đâu:
strace -p <pid> # gan vao tien trinh dang treo, xem no dung o loi goi nao
Lệnh cuối là chỗ strace không thể thay thế: một tiến trình đứng im, gắn vào, và dòng cuối cùng hiện ra cho biết nó đang chờ gì — futex, read, connect, flock.
Đo thời gian từng lời gọi:
strace -T -e trace=read,write ./chuong-trinh # -T in thoi gian moi loi goi
strace -r ./chuong-trinh # -r in khoang cach giua cac loi goi
Con số -T in ra đã bao gồm phần chi phí của chính strace, nên đừng dùng nó để so sánh hiệu năng. Nó chỉ hữu ích để tìm lời gọi nào chậm bất thường so với các lời gọi khác trong cùng lần chạy.
Ba lưu ý khi gắn vào tiến trình đang chạy
Gắn vào là dừng tiến trình. Trong khoảnh khắc strace -p gắn vào, tiến trình bị dừng. Với dịch vụ đang phục vụ, đó là một khoảng gián đoạn thật.
Thoát ra không phải lúc nào cũng sạch. Nếu strace bị giết bằng SIGKILL thay vì Ctrl-C, tiến trình bị theo dõi có thể ở lại trạng thái dừng. Luôn thoát bằng Ctrl-C.
Cần quyền. ptrace_scope mặc định là 1 trên nhiều bản phân phối, nghĩa là chỉ gắn được vào tiến trình con của chính mình:
cat /proc/sys/kernel/yama/ptrace_scope
sudo sysctl -w kernel.yama.ptrace_scope=0 # tam thoi, de go loi
Trong container cần thêm --cap-add=SYS_PTRACE.
Thử ba mươi giây
Đo tần suất lời gọi hệ thống của một dịch vụ trước khi quyết định có gắn strace hay không:
p=<pid>
perf stat -e raw_syscalls:sys_enter -p $p -- sleep 5 2>&1 | grep -E 'sys_enter|elapsed'
Lấy số lời gọi chia cho 5 giây. Nhân với 49 µs — chi phí strace đo được ở trên — ra thời gian CPU mà strace sẽ thêm vào mỗi giây.
Nếu kết quả vượt một giây, strace sẽ làm dịch vụ đứng hẳn. Lúc đó hãy dùng perf stat hoặc eBPF, hoặc dựng lại vấn đề trên một bản sao.
Phần sau: perf — đo cách tìm hàm tốn CPU nhất.
