strace -c làm chương trình chậm 446 lần dù nó không in ra một dòng nào — cái giá không nằm ở việc ghi chép, mà ở chỗ mỗi lời gọi phải dừng lại bốn lần

Hãy tưởng tượng một nhà máy đặt thanh tra đứng ngay cửa: mỗi lần công nhân bước ra hay bước vào đều phải dừng lại, trình giấy tờ, chờ ghi sổ, rồi mới đi tiếp. Nếu công nhân chỉ ra vào vài lần một ca, chẳng ai để ý. Nhưng nếu họ ra vào một triệu lần, cả dây chuyền tê liệt — không phải vì tờ giấy tốn kém, mà vì cái nhịp dừng lại nhân lên hàng triệu. strace là đúng anh thanh tra đó, và bài này đo xem cái nhịp dừng ấy đắt tới mức nào. 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ụ.

strace là công cụ tôi đã dùng ở phần 25 để đếm lời gọi hệ thống. Giờ ta đo chính cái giá của việc dùng nó.

Bảng số

Chương trình gọi write() 300.000 lần vào /dev/null:

-c chẳng cứu được gì

Đây là điều làm tôi bất ngờ nhất khi đo. 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, đúng không? Vậy mà nó chậm 446 lần, so với 501 lần của bản in đầy đủ ra tệp. Chênh nhau vỏn vẹn 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. Mọi thứ khớp.

Nói thẳng để khỏi hiểu lầm: 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 — tờ giấy không tốn, cái nhịp dừng mới tốn.

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. Anh thanh tra vẫn đứng đó, nhưng công nhân chẳng ra vào cửa lần nào nên chẳng ai bị chặn. Đây là điều cốt lõi để 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 — đếm bằng cái máy đếm gắn sẵn ở cửa, thay vì bắt từng người dừng lại.

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

Đừng vội bỏ nó — 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 chẳ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.

Mẫu số chung: quan sát bằng cách chặn từng sự kiện thì đắt theo lượng sự kiện

Cái ranh giới ở đây — chặn-và-đọc từng sự kiện (đắt, tỷ lệ theo số sự kiện) so với để một bộ đếm gắn sẵn tự tăng (rẻ, không xâm lấn) — không riêng gì strace với perf. Nó lặp lại ở mọi tầng đo lường.

Trong thế giới Java, đây đúng là khác biệt giữa gắn một agent JVMTI bẫy mọi lần vào/ra method (dừng luồng ở từng điểm, làm chậm gấp bội, y hệt ptrace) và đọc các counter có sẵn qua JMX / Micrometer, hay để async-profiler lấy mẫu. Muốn theo từng lời gọi thì trả giá theo số lời gọi; muốn con số tổng hợp thì đọc bộ đếm gần như miễn phí.

Trong Go, cùng đánh đổi: bật runtime/trace ghi từng sự kiện scheduler/GC cho bạn dòng thời gian chi tiết nhưng nặng và chỉ nên bật từng đợt ngắn, còn runtime.ReadMemStats hay các counter trong expvar/Prometheus là đọc số đã cộng sẵn, rẻ tới mức scrape liên tục được. Chi tiết-từng-sự-kiện đổi bằng chi phí theo lượng sự kiện.

Còn ở cơ sở dữ liệu, đây là khác biệt giữa bật full statement logging / auto_explain ghi mọi câu (chính xác từng câu nhưng làm ngập I/O khi tải cao) và đọc pg_stat_statements — bộ đếm cộng dồn trong engine, cập nhật gần như miễn phí, đủ để xếp hạng câu query nóng mà không phải bẫy từng lần thực thi.

Mẫu số chung: công cụ nào phải chặn/ghi lại từng sự kiện riêng lẻ đều có chi phí tỷ lệ với số sự kiện — nên nó rẻ với tải thấp và giết chết hệ thống ở tải cao, đúng lúc bạn cần nhìn nhất; còn bộ đếm cộng-sẵn thì rẻ bất kể tải, nhưng chỉ cho con số tổng chứ không cho chi tiết từng lần. Nên câu hỏi đúng trước khi bật một công cụ quan sát không phải "nó cho tôi thấy chi tiết tới đâu" mà là "chi phí của nó tỷ lệ với số sự kiện hay là hằng số, và tải hiện tại có bao nhiêu sự kiện mỗi giây" — vì chỉ cần một phép nhân đơn giản là biết nó sẽ vô hại hay làm dịch vụ đứng hẳn.

Trước khi gắn strace vào bất cứ dịch vụ nào, làm đúng phép nhân đó:

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.