Chi phí của strace

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.

Một lần tôi đo hớ: kẻ nói dối lớn nhất là 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. Bài học đo lường cuối cùng và bao trùm: để đ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ì sao điều này quan trọng khi lập trình

Hệ quả đầ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.

Hệ quả 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.

Hệ quả thứ ba, 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. Con số mang theo: 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; 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 đó.

Thử ba mươi giây

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.