Đọc syscall bằng strace — nhìn chương trình gọi kernel

TL;DR: strace là công cụ Linux ghi lại mọi system call một chương trình phát ra, kèm đối số và giá trị trả về. Nó dựa trên system call ptrace(2) — cơ chế cho một tiến trình theo dõi tiến trình khác. Mỗi dòng có dạng tên(đối_số...) = giá_trị_trả_về; lỗi hiện thành = -1 ENOENT (mô tả). Bốn nhóm hay gặp: file (openat, read, write, close), memory (mmap, brk, mprotect), process (execve, clone, wait4, exit_group), network (socket, connect, sendto). Dùng strace -c để đếm và xếp hạng syscall theo thời gian; dùng strace -p PID để soi một tiến trình đang treo — dòng cuối đứng im cho biết nó đang chờ ở đâu (thường read, futex, poll).

Ở ba bài trước, "system call" còn là khái niệm — bạn tin rằng chương trình gọi kernel, nhưng chưa thấy. Bài này biến nó thành thứ sờ được. Chỉ với một lệnh, bạn nhìn được toàn bộ cuộc đối thoại giữa chương trình và hệ điều hành: từng file nó mở, từng byte nó đọc, từng lần nó xin thêm bộ nhớ.

strace không chỉ để học. Nó là công cụ chẩn đoán hàng ngày: khi một service treo mà không log gì, khi một chương trình chậm bí ẩn, khi một lệnh báo "permission denied" mà bạn không rõ file nào — strace cho câu trả lời trong vài giây. Bài này dạy bạn đọc output của nó và rút ra kết luận.

1. Analogy — máy ghi âm cuộc gọi tổng đài

Ở bài 02, mỗi system call là một cú "gọi tổng đài" nhờ kernel làm việc. strace giống như đặt một máy ghi âm lên đường dây đó: nó không thay đổi cuộc gọi, chỉ chép lại từng câu — chương trình xin gì, kernel trả gì.

Bản ghi âm này cực kỳ hữu ích khi có sự cố. Chương trình "không mở được file"? Nghe lại băng, thấy nó gọi openat("config.yaml") và nhận về ENOENT — file không tồn tại, không phải bug code. Chương trình treo? Băng dừng ở read(...) và không có câu trả lời nào tiếp theo — nó đang ngồi chờ dữ liệu.

2. strace là gì — cơ chế ptrace

strace chạy (hoặc gắn vào) một chương trình và in ra mọi system call nó thực hiện. Dạng dùng cơ bản:

strace ./chuong_trinh          # chay va trace tu dau
strace -f ./chuong_trinh       # trace ca tien trinh con (fork/clone)
strace -p 12345                # gan vao tien trinh dang chay co PID 12345
strace -o log.txt ./ct         # ghi trace ra file thay vi man hinh

Nó làm được điều này nhờ một system call tên ptrace(2) — chính là cơ chế mà debugger (như gdb) dùng. ptrace cho phép một tiến trình "cha theo dõi" (ở đây là strace) chặn tiến trình đích mỗi khi tiến trình đó vào và ra một system call. Tại mỗi điểm chặn, strace đọc thanh ghi của tiến trình đích để biết số hiệu syscall và đối số (nhớ bài 02: số hiệu ở rax, đối số ở rdi/rsi/rdx...), giải mã ra dạng người đọc được, rồi cho tiến trình chạy tiếp.

sequenceDiagram
    participant T as strace (theo doi)
    participant P as Tien trinh dich
    participant K as Kernel
    P->>K: bat dau mot syscall
    K-->>T: ptrace chan (syscall-enter)
    T->>T: doc rax/rdi/rsi -> in "openat(...)"
    T->>K: cho tien trinh chay tiep
    K->>K: chay handler syscall
    K-->>T: ptrace chan (syscall-exit)
    T->>T: doc rax -> in "= 3"
    T->>P: cho chay tiep toi syscall ke

3. Đọc một dòng strace

Cấu trúc mỗi dòng luôn giống nhau:

openat(AT_FDCWD, "/etc/hosts", O_RDONLY|O_CLOEXEC) = 3
  \____/  \___________________________________/   \_/
  ten     doi so (giong tham so ham C)             gia tri tra ve

• Tên: openat — system call được gọi.
• Đối số: giống tham số của hàm C tương ứng. strace giải mã cả hằng số (O_RDONLY) và chuỗi ("/etc/hosts") cho dễ đọc.
• Giá trị trả về: = 3 — openat trả về một file descriptor (số 3; 0/1/2 là stdin/stdout/stderr đã dùng).

Lỗi hiện rất rõ:

openat(AT_FDCWD, "khong_ton_tai.txt", O_RDONLY) = -1 ENOENT (No such file or directory)

Nhớ bài 02: kernel trả -errno; strace dịch -2 thành tên hằng ENOENT và mô tả (No such file or directory). Đây là dòng bạn săn khi chương trình "không tìm thấy file" hay "permission denied" (EACCES).

Đây là đoạn đầu điển hình khi chạy strace ls (rút gọn — số và địa chỉ thật sẽ khác trên máy bạn):

execve("/usr/bin/ls", ["ls"], 0x7ffe... /* 30 vars */) = 0
brk(NULL)                               = 0x55e...
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=41547, ...}) = 0
mmap(NULL, 41547, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f...
close(3)                                = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0"..., 832) = 832
mmap(NULL, 2020..., PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f...
mprotect(0x7f..., 16384, PROT_READ)     = 0
close(3)                                = 0
write(1, "Documents  Downloads  file.txt\n", 31) = 31
exit_group(0)                           = ?

Ngay cả khi chưa hiểu từng syscall, bạn thấy được câu chuyện: chương trình khởi động (execve), nạp thư viện C (openat + read + mmap cái libc.so.6), làm việc của nó (write kết quả ra stdout), rồi thoát (exit_group).

4. Bốn nhóm syscall thường gặp

Không ai đọc từng dòng. Mẹo là phân nhóm để nắm bức tranh lớn:

strace có thể lọc theo nhóm sẵn:

strace -e trace=file    ./ct     # chi syscall lien quan file/path
strace -e trace=network ./ct     # chi syscall mang
strace -e trace=memory  ./ct     # chi syscall bo nho
strace -e trace=%process ./ct    # chi syscall vong doi tien trinh

Khi debug "chương trình mở nhầm file", strace -e trace=file cắt hết nhiễu, chỉ để lại các thao tác path — thường thấy ngay dòng ENOENT thủ phạm. Các nhóm này ánh xạ trực tiếp về các phần cứng/tài nguyên mà bài 01 nói user code phải xin qua kernel.

5. strace -c — đâu là syscall đắt nhất?

Với chương trình phát hàng nghìn syscall, đọc dòng-theo-dòng là bất khả thi. Cờ -c gom lại thành bảng tổng hợp: đếm mỗi loại syscall được gọi bao nhiêu lần, tổng thời gian, và số lỗi.

strace -c ls

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 24.30    0.000112           7        16           mmap
 18.20    0.000084           8        10         3 openat
 15.10    0.000070           5        13           close
 12.00    0.000055           4        12           read
  9.80    0.000045           6         7           fstat
  8.10    0.000037          12         3           write
  ...
------ ----------- ----------- --------- --------- ----------------
100.00    0.000461                    78         3 total

Cách đọc bảng (con số cụ thể thay đổi theo máy — điều đáng chú ý là hình dạng):

• Cột calls: syscall nào bị gọi nhiều nhất. Nhiều read/write bất thường gợi ý I/O không có buffer.
• Cột errors: syscall nào trả lỗi. Ở đây openat có 3 lỗi — thường là tìm thư viện/config ở nhiều chỗ, có chỗ ENOENT (bình thường), nhưng số lỗi lớn bất thường đáng điều tra.
• Cột % time / seconds: syscall nào ngốn thời gian nhất. Đây là nơi bắt đầu tối ưu — dù nhớ cảnh báo section 2 rằng thời gian dưới strace bị phóng đại.

strace -c chính là công cụ trả lời câu "chương trình này chậm vì gọi quá nhiều syscall gì?" — nối thẳng với bài học chi phí syscall ở bài 02.

6. Chẩn đoán treo và chậm

Chương trình treo. Một service không phản hồi nhưng CPU gần 0%: nó không bận tính, mà đang chờ một syscall block. Gắn strace vào nó:

strace -p 12345

Nếu output đứng im ở một dòng chưa có =:

read(6,

thì tiến trình đang kẹt trong read trên fd 6, chờ dữ liệu không bao giờ tới (có thể là socket phía kia không gửi, hay pipe rỗng). Vài syscall "chờ" hay gặp:

• read(... / recvfrom(... — chờ dữ liệu file/socket.
• futex(... — chờ một lock/điều kiện (thường là deadlock hoặc lock bị giữ; sẽ học ở module đồng bộ).
• poll(... / epoll_wait(... — chờ sự kiện I/O trên nhiều fd.
• wait4(... — cha đang chờ tiến trình con kết thúc.

Dòng cuối đứng im chính là chỗ nó treo — thông tin vàng mà không log nào cho bạn.

Chương trình chậm. Chạy strace -c (chậm nhiều syscall?) hoặc strace -T (in thời gian mỗi call trong <...>):

strace -T ./ct

read(3, "x", 1)   = 1 <0.000004>
read(3, "y", 1)   = 1 <0.000005>
read(3, "z", 1)   = 1 <0.000004>
... (hang nghin dong read 1 byte)

Nghìn dòng read(...1) = 1 là dấu hiệu kinh điển của đọc không buffer: mỗi byte một syscall, mỗi syscall một mode switch. Fix: đọc theo khối lớn (nhớ bài 02 — gom thành ít syscall lớn).

7. Thử sức — tự đọc một trace

Dưới là trace rút gọn của một chương trình. Trước khi đọc phân tích, hãy tự trả lời: chương trình này làm gì, và có gì bất thường không?

execve("/usr/bin/app", ["app"], ...)    = 0
openat(AT_FDCWD, "/etc/app/config.yaml", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/home/u/.app.yaml", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "./config.yaml", O_RDONLY) = 3
read(3, "port: 8080\n", 4096)           = 11
close(3)                                = 0
socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 4
connect(4, {sa_family=AF_INET, sin_port=htons(5432), ...},

Phân tích:

• Hai openat đầu trả ENOENT không phải lỗi — đây là chương trình tìm file config theo thứ tự ưu tiên (thư mục hệ thống, rồi home), không thấy thì thử chỗ tiếp. Đến ./config.yaml mới thấy (= 3). Đây là mẫu "search path" rất thường gặp; đừng hoảng khi thấy ENOENT kiểu này.
• Nó read config thấy port: 8080.
• Rồi mở một socket TCP (= 4) và gọi connect tới cổng 5432 (cổng mặc định của PostgreSQL). Dòng connect chưa có giá trị trả về — trace dừng ở đây, nghĩa là chương trình đang kẹt khi kết nối database. Nhiều khả năng database không chạy hoặc firewall chặn: đây chính là chỗ treo.

Chỉ từ trace, không cần đọc source, bạn kết luận được: chương trình đọc config OK, nhưng treo khi kết nối PostgreSQL ở cổng 5432.

8. Pitfall — những hiểu nhầm thường gặp

❌ Nhầm 1 — "Mọi dòng ENOENT/= -1 là bug cần sửa."

✅ Không. Rất nhiều lỗi trong trace là bình thường và có chủ đích: tìm thư viện/config qua nhiều đường dẫn, thử một tính năng kernel rồi fallback. Chỉ quan tâm lỗi ở chỗ không nên có — ví dụ read một fd hợp lệ mà trả EIO.

❌ Nhầm 2 — "Thời gian trong strace -c là tốc độ thật của chương trình."

✅ Không. strace chặn mỗi syscall hai lần nên làm chương trình chậm đi và phóng đại thời gian syscall. Dùng con số để so tỉ lệ giữa các syscall và tìm hot spot, không phải để đo tốc độ tuyệt đối. Benchmark thật thì chạy không có strace.

❌ Nhầm 3 — "strace cho thấy mọi thứ chương trình làm."

✅ Chỉ thấy system call — tức những lần chạm kernel. Toàn bộ tính toán trong user mode (vòng lặp, xử lý chuỗi, thuật toán) vô hình với strace. Một chương trình đốt CPU 100% trong một vòng lặp thuần user sẽ cho trace trống trơn — lúc đó cần perf hay profiler, không phải strace.

9. 📚 Deep Dive

10. Liên hệ các bài khác

• Bài 02 — System call là gì: strace hiện đúng những syscall bạn đã học ở mức thanh ghi; giá trị trả về âm (-errno) chính là thứ hiện thành -1 ENOENT.
• Bài 03 — Interrupt, trap & exception: strace cũng in các signal (SIGSEGV, SIGPIPE) mà exception và sự kiện sinh ra, không chỉ syscall.
• Bài 05 — Mini-challenge đếm syscall: bạn tự cầm strace -c mổ xẻ một lệnh thật — áp dụng trực tiếp bài này.
• Bài 01 — Kernel mode vs user mode: bốn nhóm syscall ánh xạ về các tài nguyên phần cứng mà user code phải xin qua kernel.

11. Tóm tắt

• strace ghi lại mọi system call của một chương trình, dựa trên ptrace(2) — cơ chế một tiến trình theo dõi tiến trình khác (cùng nền với gdb).
• Mỗi dòng: tên(đối_số) = kết_quả; lỗi hiện = -1 TÊNLỖI (mô tả), ví dụ -1 ENOENT khi file không tồn tại.
• Phân bốn nhóm để đọc nhanh: file (openat/read/write), memory (mmap/brk), process (execve/clone/wait4), network (socket/connect/sendto). Lọc bằng -e trace=file|network|memory|%process.
• strace -c xếp hạng syscall theo calls / errors / thời gian — tìm hot spot và anti-pattern (nghìn read 1 byte).
• strace -p PID soi tiến trình đang treo: dòng cuối đứng im (read, futex, poll, wait4) chỉ ra chỗ nó chờ.
• Cảnh giác: nhiều ENOENT là bình thường (search path); thời gian dưới strace bị phóng đại; strace không thấy tính toán thuần trong user mode.

12. Tự kiểm tra

Bài tiếp theo: Mini-challenge — mổ xẻ một lệnh bằng strace