Ở bài trước perf cho ta nhìn CPU làm gì ở mức phần cứng — nhưng nó cần một PMU mà máy ảo giấu mất. Có một cách nhìn khác, không cần phần cứng đặc biệt: xem chương trình nói chuyện với nhân như thế nào — nó gọi những lời gọi hệ thống (syscall) nào, bao nhiêu lần, với tham số gì. Công cụ kinh điển cho việc đó là strace. Bài này dùng nó soi một chương trình thật, và đo luôn cái giá của chính việc soi — một cái giá lớn đến mức đổi hẳn cách tôi nghĩ về công cụ này.
strace và ltrace bẫy hai tầng khác nhau
Một chương trình chạy trên Linux liên tục nhờ nhân làm hộ những việc nó không tự làm được: mở file, ghi dữ liệu, cấp bộ nhớ, tạo tiến trình. Mỗi việc như vậy là một syscall — một lời gọi vượt ranh giới từ chương trình (user space) xuống nhân (kernel space). strace bắt (bẫy) mọi syscall này và in ra: tên, tham số, giá trị trả về. Cơ chế của nó là ptrace — cùng thứ mà trình gỡ lỗi (debugger) dùng: nhân dừng chương trình ở mỗi syscall, hai lần (một lúc vào syscall, một lúc ra), chuyển quyền sang tiến trình theo dõi (strace) để nó đọc, rồi mới cho chạy tiếp.
ltrace là anh em của strace nhưng bẫy ở một tầng cao hơn: nó bắt các lời gọi hàm thư viện (thường là libc — malloc, printf, strlen, strcpy...), chứ không phải syscall. Đây là điểm hay bị lẫn: hai công cụ nhìn hai tầng khác nhau. Một hàm libc như printf có thể gọi không hay nhiều syscall bên dưới — printf ghi vào bộ đệm có thể chẳng gọi write nào cho tới khi bộ đệm đầy, rồi gọi một write gộp. Nên strace không thấy printf (nó ở tầng thư viện), còn ltrace không thấy trực tiếp write (nó ở tầng syscall). Muốn hiểu chương trình đầy đủ đôi khi cần cả hai, mỗi cái soi một tầng.
Đo: strace làm chương trình chậm 270 lần
Tôi viết một chương trình C cố tình gọi nhiều syscall: ghi 8 byte vào /dev/null đúng 200.000 lần (mỗi vòng lặp là một write). Rồi đo thời gian chạy của nó trong hai điều kiện — không có và có strace:
KHÔNG strace : ~26 ms (5 lần đo: 26, 26, 26, 29, 24)
DƯỚI strace : ~7144 ms (3 lần đo: 7127, 7173, 7144)
Chậm đi khoảng 270 lần. Không phải 2 lần, không phải 10 lần — 270 lần. Lý do nằm ở cơ chế ptrace: mỗi write giờ không còn là một chuyến đi nhanh xuống nhân rồi về, mà thành một chuỗi dài: chương trình dừng → nhân chuyển ngữ cảnh sang strace → strace đọc thanh ghi, ghi log → cho chạy tiếp → chạy được đúng cái syscall → dừng lần nữa lúc ra → lại chuyển sang strace. Hai lần chuyển ngữ cảnh cho mỗi syscall, với 200.000 syscall, cộng lại thành hàng trăm mili giây phụ trội — nuốt trọn 26 ms công việc thật.
strace -c cho một góc nhìn khác: nó không in từng dòng mà đếm syscall theo loại và tổng hợp:
% time seconds usecs/call calls syscall
100.00 0.731353 3 200000 write
0.00 0.000000 0 6 mmap
0.00 0.000000 0 3 openat
...
Bảng này cực hữu ích để biết chương trình gọi syscall nào nhiều nhất — ở đây write chiếm 100%, đúng như thiết kế. Nhưng chính cái cột seconds trong bảng này là nơi tôi vấp.
Một lần tôi đo hớ: cột "seconds" không phải chi phí thật
Nhìn dòng write : 0,731353 seconds, phản xạ đầu tiên của tôi là kết luận: "à, chương trình tốn 0,73 giây cho các lời write". Con số nằm ngay đó, có đơn vị giây đàng hoàng, trông như một phép đo hiệu năng chuẩn.
Nhưng nó mâu thuẫn thẳng với phép đo bằng đồng hồ: chạy không strace, cả chương trình — 200.000 write và mọi thứ khác — chỉ mất 26 mili giây. Làm sao "riêng phần write" lại tốn 0,73 giây (730 ms) khi cả chương trình chỉ 26 ms? Hai con số chọi nhau, và theo đúng kỷ luật của sê-ri, hai số mâu thuẫn nghĩa là tôi đang đo nhầm đại lượng.
Sự thật: cột seconds của strace -c đo thời gian nằm trong mỗi syscall khi đang bị ptrace bẫy — tức đã bao gồm chi phí chuyển ngữ cảnh sang tracer, đã phồng to lên bởi chính việc theo dõi. Nó không phải thời gian syscall thật khi chương trình chạy tự do. Cái con số 0,73 giây đó chỉ nói được một điều đúng: phân bố tương đối — write chiếm 100% thời gian trong số các syscall, tức nếu tối ưu thì nhắm vào write. Nhưng lấy nó làm chi phí tuyệt đối là sai một trời một vực (730 ms so với thực tế 26 ms). Tôi tin đồng hồ (/usr/bin/time, clock_gettime) hơn con số mà chính công cụ theo dõi tự báo về mình.
Bài học đo lường: strace/ltrace là kính hiển vi để THẤY chương trình gọi gì, không phải đồng hồ để đo nó NHANH hay CHẬM. Đừng bao giờ đo hiệu năng của một chương trình dưới strace — bản thân việc soi đã làm nó chậm hàng trăm lần, mọi con số thời gian bạn đọc được đều là thời gian của "chương trình bị soi", không phải chương trình thật. Muốn biết nó gọi syscall nào, gọi bao nhiêu lần: strace. Muốn biết nó nhanh hay chậm: bỏ strace ra, đo bằng đồng hồ. Hai câu hỏi, hai công cụ.
Còn ltrace? Trong máy này which ltrace trả về rỗng — nó vắng, dù strace có sẵn. Đó cũng là một điều đáng ghi: hai công cụ tưởng như một cặp lại không phải lúc nào cũng cùng có mặt, và chúng bẫy hai tầng khác nhau (syscall với hàm thư viện) nên không thay thế được cho nhau. Khi cần soi lời gọi libc mà không có ltrace, có thể dùng gdb đặt điểm dừng, hoặc LD_PRELOAD chèn hàm bọc — nhưng đó là chuyện của một bài khác.
Vì sao điều này quan trọng khi lập trình
Hệ quả đầu tiên là strace là công cụ gỡ lỗi mạnh nhất khi chương trình "im lặng" hỏng. Một chương trình báo lỗi mơ hồ ("không mở được file") mà không nói file nào, đường dẫn nào — chạy nó dưới strace -f và bạn thấy ngay dòng openat(AT_FDCWD, "/etc/cai-gi-do", O_RDONLY) = -1 ENOENT (No such file or directory): đúng file, đúng đường dẫn, đúng lý do. Nó cắt xuyên qua mọi tầng trừu tượng của thư viện và framework để cho bạn thấy chương trình thật sự yêu cầu gì ở hệ điều hành. Cấu hình sai, thiếu quyền, tìm file ở sai chỗ, kẹt ở một read mạng không bao giờ trả về — strace phơi bày hết.
Hệ quả thứ hai là hiểu cái giá của việc quan sát để không đo nhầm. Nguyên tắc chung: mọi công cụ theo dõi đều làm thay đổi thứ nó theo dõi (hiệu ứng quan sát). strace là ví dụ cực đoan — 270 lần — vì nó bẫy ở tầng syscall bằng ptrace, một cơ chế đắt. Điều này cũng gợi ý khi nào strace đắt: một chương trình gọi rất nhiều syscall (I/O dày đặc, mạng bận rộn) sẽ chậm thảm hại dưới strace; một chương trình tính toán thuần trong bộ nhớ (ít syscall) thì gần như không hề hấn. Nếu phải theo dõi một hệ thống đang chạy thật mà không thể chịu 270 lần chậm, có các công cụ tầng thấp hơn nhiều (eBPF, perf trace) lấy mẫu thay vì bẫy từng cái — nhưng đó là đánh đổi độ chi tiết lấy tốc độ.
Hệ quả thứ ba là một bài học tư duy: phân biệt "công cụ cho thấy" và "công cụ đo lường". Con số mang theo: strace bẫy mỗi syscall bằng ptrace (hai lần dừng mỗi lời gọi) và làm chương trình nhiều syscall chậm ~270 lần; nó cho biết chương trình gọi GÌ và bao nhiêu lần — không phải chương trình NHANH hay CHẬM bao nhiêu; cột seconds của strace -c là thời gian dưới ptrace, chỉ dùng để so phân bố tương đối chứ đừng đọc như chi phí thật. Dùng đúng công cụ cho đúng câu hỏi: strace/ltrace để nhìn hành vi, /usr/bin/time và clock_gettime để đo tốc độ, perf để nhìn phần cứng. Lẫn lộn chúng là con đường chắc chắn dẫn tới một kết luận nghe rất có căn cứ mà sai hoàn toàn.
Thử ba mươi giây
Trên một máy Linux, chọn một lệnh quen thuộc và soi nó: strace -c ls / (hoặc strace -c curl -s example.com). Bạn sẽ thấy một bảng tổng hợp các syscall — openat, read, write, mmap, stat... — với số lần gọi mỗi loại. Hãy nhìn syscall nào có số calls cao nhất: đó là cái chương trình làm nhiều nhất với hệ điều hành. Rồi thử strace ls / (không có -c) để thấy từng dòng syscall trôi qua — mỗi dòng là một lần chương trình nhờ nhân làm việc. Nhưng nhớ điều bài này đo: đừng dùng những con số thời gian trong đó để kết luận lệnh nhanh hay chậm — muốn biết tốc độ thật, chạy /usr/bin/time -v ls / mà không có strace bọc quanh.
