Công cụ tôi tin nhất suốt cả sê-ri hóa ra là kẻ nói dối lớn nhất về thời gian

Suốt sê-ri này tôi dùng strace để đếm và soi lời gọi hệ thống — nó chỉ ra sendfile gọi 1 syscall thay vì 16.384, nó cho thấy getpid có qua vDSO hay không, nó lộ ra ENFILE thay vì EMFILE. Nhưng bản thân strace tốn bao nhiêu? Nó làm chương trình bị theo dõi chậm đi mức nào? Bài này đo trực tiếp — và câu trả lời biến chính công cụ đo tin cậy nhất của tôi thành minh họa hoàn hảo cho bài học lớn nhất của cả sê-ri.

strace theo dõi bằng ptrace

strace chặn mọi lời gọi hệ thống của chương trình bằng cơ chế ptrace. Cách nó làm: mỗi khi tiến trình bị theo dõi bắt đầu một syscall, nhân dừng tiến trình đó lại và chuyển quyền điều khiển sang strace (một cú chuyển ngữ cảnh sang tiến trình theo dõi); strace đọc các thanh ghi để biết syscall gì với tham số nào, ghi lại, rồi cho tiến trình chạy tiếp; và khi syscall kết thúc, lại dừng lần nữa để ghi giá trị trả về. Nghĩa là mỗi một syscall giờ kéo theo mấy cú dừng-và-chuyển-ngữ-cảnh giữa tiến trình bị theo dõi và strace.

Hệ quả trực tiếp: chi phí của strace dồn hết vào mỗi syscall. Một chương trình gọi nhiều syscall sẽ chậm đi khủng khiếp; một chương trình thuần tính toán (ít hoặc không syscall) gần như không bị ảnh hưởng, vì chẳng có gì để strace chặn. Tôi muốn đo cụ thể "khủng khiếp" là bao nhiêu.

Đo: mỗi syscall đắt 630 lần, nhưng chỉ syscall

Tôi viết hai chương trình. A: gọi getpid() nhiều triệu lần (một syscall thật mỗi vòng, gần như không làm gì khác). B: một vòng lặp tính toán thuần, không gọi syscall nào. Rồi chạy mỗi cái ba cách — không strace, dưới strace -f -o /dev/null (ghi đầy đủ ra hư vô), và strace -c (chỉ tổng kết):

Con số gây choáng: một getpid bình thường tốn 126 nano giây; dưới strace, nó tốn 79.536 nano giây — gần 80 micro giây, chậm hơn 630 lần. Mỗi lần gọi, tiến trình phải dừng lại, nhường CPU cho strace ghi chép, rồi mới chạy tiếp. Đáng chú ý, strace -c (chỉ in bảng tổng kết cuối, không in từng dòng) cũng tốn ~71 micro giây mỗi syscall — chỉ rẻ hơn chút, vì dù không in ra nó vẫn phải ptrace dừng ở mỗi syscall; cái đắt là việc dừng, không phải việc in.

Còn chương trình B (thuần CPU) thì:

bare: 3 ns/vòng   |   strace: 2 ns/vòng   (không đổi)

Không khác gì. Vì vòng lặp tính toán không gọi syscall nào, strace chẳng có gì để chặn, nên nó ngồi im và chương trình chạy hết tốc lực. Điều này khẳng định: strace làm chậm hoàn toàn theo số syscall, không theo lượng tính toán. Một chương trình bị strace chậm gấp 100 lần thì nó đang gọi rất nhiều syscall; một chương trình không hề chậm đi thì nó gần như không gọi syscall nào.

Kẻ nói dối lớn nhất là chính công cụ đo

Đây là đỉnh của bài học lặp lại suốt sê-ri, và tôi phải thú thật nó chính là cái bẫy tôi đã bước vào nhiều lần. strace là công cụ tôi tin dùng để soi syscall ở gần như mọi bài. Nhưng nó làm nhiễu chính thứ nó đo một cách dữ dội — đây là hiệu ứng người quan sát ở dạng thuần khiết nhất: hành động quan sát đã thay đổi kết quả. Mỗi syscall dưới strace chậm 630 lần, nên mọi con số thời gian đo được trong khi strace đang bám vào đều sai, bị thổi phồng khủng khiếp.

Và tôi đã dính đúng chuyện này: ở bài về sendfile, khi chạy dưới strace thì read+write tụt xuống còn 661 MB/s — không phải vì read+write chậm, mà vì strace phạt mỗi trong 16.384 syscall của nó. Nếu tôi tin con số 661 MB/s đó, tôi đã kết luận sai hoàn toàn về hiệu năng.

Điều này lật ngược câu maxim tôi lặp suốt sê-ri — "tin đồng hồ hơn bộ đếm". Khi strace bám vào, sự thật đảo chiều: đừng tin đồng hồ, hãy tin bộ đếm. strace đếm số và loại syscall cực kỳ chính xác (đó là việc của nó, và nó làm đúng) — nhưng thời gian nó cho bạn thấy là dối, vì chính nó đã thêm 80 micro giây vào mỗi syscall. Công cụ trung thực về cái nó đếm, nhưng dối về thời gian khi nó đang nhìn. Điều rút ra cuối cùng và bao trùm cả sê-ri: để đo thật một thứ, đôi khi bạn không được nhìn nó quá sát — chính hành động quan sát đã bóp méo kết quả. Đo số và đo thời gian phải tách làm hai lần: dùng strace để biết gì xảy ra, rồi bỏ strace ra để đo bao lâu.

Về đến code hằng ngày

Điều đầu tiên là đừng bao giờ đọc con số thời gian đo được trong khi strace đang chạy. Nếu bạn strace một chương trình để gỡ lỗi, mọi cảm nhận "nó chạy chậm quá" là vô nghĩa — chính strace làm nó chậm. Đo hiệu năng phải làm không có strace; dùng strace chỉ để biết nó gọi syscall gì và bao nhiêu lần. Trộn hai mục đích là tự lừa mình.

Điều thứ hai là chọn công cụ theo mức xâm lấn. strace (dựa trên ptrace) rất tiện nhưng nặng — không dùng được trên môi trường production nhạy hiệu năng, vì nó có thể làm dịch vụ chậm trăm lần và lệch cả hành vi thời gian (một số bug biến mất dưới strace vì nó đổi timing). Khi cần quan sát mà không làm chậm nhiều, dùng công cụ dựa trên eBPF (bpftrace, strace --seccomp-bpf, hay perf trace) — chúng chạy trong nhân, không dừng tiến trình ở mỗi syscall, nên rẻ hơn nhiều bậc. Biết chi phí của công cụ giúp chọn đúng cho từng việc.

Điều cuối, là kết cho cả sê-ri về đo lường: công cụ đo là một biến, và đôi khi là biến lớn nhất. Gói lại bằng số: strace phạt mỗi syscall ~80 micro giây (so với 126 nano giây bình thường, chậm 630 lần) vì nó dừng tiến trình ở mỗi syscall qua ptrace — nên chương trình nhiều syscall chậm hàng trăm lần dưới strace, còn chương trình thuần CPU không đổi (3 vs 2 ns); strace đếm syscall chính xác nhưng làm sai hoàn toàn thời gian, nên đừng tin đồng hồ khi nó đang bám. Suốt sê-ri này, thứ nói dối tôi nhiều nhất không phải hệ điều hành, mà là chính những công cụ tôi dùng để đo nó — và bài học lớn nhất là luôn nhớ điều đó.

Cái "hiệu ứng người quan sát" này không phải đặc sản của C hay Linux — nó rình mọi lập trình viên đang bật một công cụ chẩn đoán để đo hiệu năng. Trong Java, chạy dưới debugger ở chế độ diễn giải (interpreted, tắt JIT) hay bật một profiler kiểu instrumentation (chèn mã vào từng lời gọi phương thức) có thể làm chương trình chậm hàng chục lần và làm lệch hẳn profile — đó chính là lý do các profiler hiện đại như async-profiler chuyển sang lấy mẫu (sampling) rẻ thay vì instrument từng method. Go cũng vậy: pprof dạng lấy mẫu gần như không nhiễu, còn bật race detector (-race) làm chương trình chậm 5–10 lần và không thể tin số thời gian. Cơ sở dữ liệu là ca kinh điển nhất: bật log_min_duration_statement = 0 (ghi log mọi câu lệnh) hay mở full query trace trên PostgreSQL có thể khiến chính việc ghi log trở thành nút thắt, và bạn đo ra "truy vấn chậm" trong khi thủ phạm là cái trace bạn vừa bật. Mẫu số chung, đúng như bài này: mỗi lần bật một công cụ để đo hay soi, hãy hỏi ngay "cái thước này có tự thêm chi phí vào thứ nó đang đo không?" — và tách bạch phép đo cái gì xảy ra với phép đo mất bao lâu, vì hiếm công cụ nào trung thực cả hai cùng lúc.

Muốn tự thấy chi phí strace: viết một vòng lặp gọi một syscall rẻ nhiều lần — python3 -c "import os; [os.getpid() for _ in range(1000000)]" — rồi chạy nó hai lần, một lần trần và một lần dưới strace -f -c python3 ..., so thời gian bằng time. Bạn sẽ thấy bản strace chậm gấp hàng chục tới hàng trăm lần. Đổi vòng lặp thành tính toán thuần (sum(i*i for i in range(1000000))) và làm lại — lần này strace gần như không làm chậm, vì không có syscall. Và bài học mang theo cả sê-ri: mỗi khi bạn đo hiệu năng, hãy hỏi "công cụ đo của mình có đang làm nhiễu kết quả không?" — vì kẻ nói dối tinh vi nhất thường chính là cái thước bạn đang cầm.