strace -c và -T: tìm chính xác syscall nào khiến chương trình chậm

Bài trước ta dùng strace để thấy chương trình làm gì. Nhưng strace còn là một công cụ đo hiệu năng bất ngờ mạnh: khi một chương trình chậm và bạn không biết chậm ở đâu, strace -c cho ngay một bảng xếp hạng — syscall nào ngốn nhiều thời gian nhất, gọi bao nhiêu lần. Rất nhiều vấn đề hiệu năng thực tế không phải do thuật toán mà do quá nhiều lời gọi hệ thống nhỏ (đọc/ghi từng byte, gọi mạng lặt vặt), và strace phơi bày chúng ngay lập tức. Bài này (phần 2 loạt Debug) đo thật một chương trình I/O tệ và cách tìm ra thủ phạm.

-c: bảng tóm tắt chỉ thẳng thủ phạm

strace -c không in từng dòng syscall mà đếm và tính thời gian, rồi in một bảng: mỗi syscall chiếm bao nhiêu % time, tổng seconds, số calls. Thường chỉ cần liếc là thấy — một hoặc hai syscall chiếm >90%.

strace -c ./chuong-trinh
# % time  seconds  calls  syscall
#  98.13  0.0879   20000  write     <- thủ phạm

Mẫu hỏng kinh điển: quá nhiều syscall nhỏ

Nguyên nhân phổ biến nhất của "chậm ngầm" là gọi syscall quá nhiều lần. Mỗi syscall là một lần chuyển từ user space vào kernel và ngược lại — rẻ cho một lần, nhưng nhân lên hàng chục nghìn thì thành gánh nặng. Ví dụ ghi từng byte một:

# CHẬM: 20000 lần ghi, mỗi lần 1 byte -> 20000 syscall write
for i in range(20000):
    os.write(fd, b"x")

# NHANH: gom lại ghi một lần -> 1 syscall write
os.write(fd, b"x" * 20000)

Hình 1: strace -c cho bảng % thời gian và số lần gọi mỗi syscall; mẫu hỏng phổ biến là quá nhiều syscall nhỏ (ghi từng byte); -T đo thời gian từng lời gọi; quy trình: đếm → giảm số lần hoặc soi cái chậm.

Đo thật: từ 20000 lời gọi xuống 1

Hình 2: Chạy thật — strace -c trên chương trình chậm: write chiếm 98.13% thời gian với 20000 lần gọi; bản gom ghi: write chỉ 1 lần, tổng syscall giảm từ 20355 xuống 356; -T cho mỗi write ~25µs; wall time 0.011s vs 0.004s.

• -c chỉ thẳng thủ phạm: bảng cho thấy write chiếm 98.13% thời gian với 20000 lần gọi. Không cần đoán — thủ phạm là số lần ghi quá nhiều, mỗi lần một byte.
• Sửa và đo lại: gom thành một write, bảng mới cho write chỉ 1 lần, tổng syscall từ 20355 xuống 356. Số lần gọi giảm ~57 lần.
• -T soi từng lời gọi: strace -T in <thời gian> sau mỗi syscall — mỗi write mất ~25µs. Một cái thì không đáng kể, nhưng 20000 × 25µs là phần lớn thời gian. -T hữu ích khi ít lời gọi nhưng nghi một cái lâu bất thường (đọc mạng treo, chờ khoá).
• Wall time: slow 0.011s vs fast 0.004s. Chênh lệch khiêm tốn ở đây vì đĩa local rất nhanh và write nhỏ được đệm — nhưng con số syscall (20000 vs 1) là tín hiệu rõ ràng, và trên đĩa mạng/chậm hoặc khi mỗi syscall thực sự chạm đĩa (fsync), khác biệt sẽ rất lớn. Đây là lý do đếm syscall quan trọng ngay cả khi wall time local nhỏ.

Quy trình chẩn đoán hiệu năng bằng strace

1. strace -c: syscall nào chiếm nhiều % time hoặc calls nhất?
2. Nếu một loại gọi rất nhiều lần → giảm số lần: gom I/O (buffer), cache kết quả, dùng thao tác hàng loạt. Đây là trường hợp phổ biến nhất.
3. Nếu ít lần nhưng mỗi cái lâu → dùng -T soi cái chậm; thường là chờ mạng, chờ khoá, hoặc đĩa chậm.

Đánh đổi cần cân nhắc

strace đo thời gian trong syscall, không đo thời gian tính toán thuần trong user space. Nếu chương trình chậm vì một vòng lặp CPU nặng (không gọi syscall), strace -c sẽ cho tổng thời gian syscall nhỏ mà chương trình vẫn chậm — vì thời gian nằm ở CPU, không ở kernel. Lúc đó cần công cụ profiling CPU (perf/pprof — bài sau), không phải strace. Dùng strace khi nghi vấn đề nằm ở I/O, mạng, hay tương tác hệ thống.

Bản thân strace làm sai lệch số đo. Vì strace dừng mỗi syscall để ghi, thời gian nó báo (và wall time khi chạy dưới strace) cao hơn thực tế. Dùng -c/-T để so tương đối giữa các syscall và tìm thủ phạm, đừng coi con số tuyệt đối là hiệu năng thật. Đo hiệu năng thật thì chạy không strace và dùng time hoặc benchmark.

Giảm syscall không phải lúc nào cũng là câu trả lời. Đôi khi số syscall cao là đúng bản chất công việc (một server xử lý nhiều kết nối). Đừng tối ưu mù số syscall; hiểu vì sao nó cao. Mẫu "ghi từng byte" rõ ràng là lỗi cần sửa; nhưng "nhiều epoll_wait" trong một event loop là bình thường.

Ba ý mang về

1. strace -c chỉ thẳng syscall tốn thời gian nhất: đo thật, chương trình ghi 20000 lần 1 byte cho write chiếm 98% thời gian với 20000 lần gọi — không cần đoán, bảng tóm tắt phơi bày thủ phạm ngay.
2. Mẫu hỏng phổ biến là quá nhiều syscall nhỏ: đo thật gom 20000 lần ghi thành 1 làm tổng syscall giảm từ 20355 xuống 356; -T cho thấy mỗi write ~25µs, nhân số lần thành phần lớn thời gian.
3. Dùng đúng công cụ: -c để đếm, -T để soi cái chậm; nhưng strace chỉ đo thời gian trong syscall (I/O/mạng) — chương trình chậm vì CPU thuần cần profiling CPU, và số strace tuyệt đối bị sai lệch nên chỉ dùng so tương đối.

Nguồn

• man7.org — strace(1) (mục -c, -T): https://man7.org/linux/man-pages/man1/strace.1.html
• Brendan Gregg — Linux Performance: https://www.brendangregg.com/linuxperf.html
• man7.org — write(2): https://man7.org/linux/man-pages/man2/write.2.html

Phần sau ta mở "cửa sổ" nhìn vào một tiến trình đang sống: thư mục /proc/<pid> — đọc trạng thái, file descriptor đang mở, bản đồ bộ nhớ, mà không cần dừng hay strace tiến trình.