"Chương trình chạy chậm." Câu này vô dụng cho việc sửa, vì "chậm" có ít nhất ba nguyên nhân hoàn toàn khác nhau: nó tính toán nhiều (nghẽn CPU), nó chờ thứ gì đó (I/O, mạng, khoá), hay nó gọi kernel quá nhiều (syscall). Ba nguyên nhân này cần ba cách sửa khác nhau — và may thay, một công cụ có sẵn trên mọi máy Unix cho bạn biết ngay là cái nào: time. Nó in ba con số real, user, sys, và tỉ lệ giữa chúng là dấu vân tay chẩn đoán. Bài này (phần 6 loạt Debug) chạy thật ba kiểu chương trình để đọc ba con số này.

Ba con số nghĩa là gì

time ./chuong-trinh
# real  thời gian THẬT trôi qua (đồng hồ tường) — bạn ngồi chờ bấy nhiêu
# user  thời gian CPU chạy CODE của bạn (user space)
# sys   thời gian CPU chạy trong KERNEL (syscall làm hộ bạn)
  • real (wall clock): tổng thời gian từ lúc bắt đầu tới lúc kết thúc — thời gian bạn thực sự chờ.
  • user: thời gian CPU tiêu cho code của bạn chạy trong user space (vòng lặp, tính toán).
  • sys: thời gian CPU tiêu trong kernel thay mặt bạn (thực thi syscall: đọc/ghi, cấp bộ nhớ).

Quan hệ then chốt: user + sys = tổng thời gian CPU thực sự làm việc. Còn real có thể lớn hơn nhiều — phần dôi ra là thời gian chờ (CPU ngồi không, đợi đĩa/mạng/khoá).

Ảnh chụp đoạn mã nền tối minh hoạ real user sys chương trình chậm do CPU hay do chờ, time cho ba con số mỗi cái nghĩa khác nhau time chuong-trinh real thời gian thật trôi qua đồng hồ tường bạn chờ bấy nhiêu user thời gian CPU chạy code của bạn user space sys thời gian CPU chạy trong kernel syscall thay bạn user cộng sys bằng tổng CPU đã dùng real có thể lớn hơn chờ, ba dấu vân tay chẩn đoán user xấp xỉ real sys nhỏ CPU-bound code tính toán nặng nghẽn ở thuật toán tối ưu code profiling CPU real lớn hơn nhiều user cộng sys đang chờ I O mạng ngủ chờ khoá CPU rảnh chờ thứ khác tìm cái đang chặn strace đĩa DB sys cao gần user quá nhiều syscall I O vụn giảm số syscall gom I O như bài strace -c, vì sao real có thể nhỏ hơn user đa lõi chạy song song nhiều lõi tổng user cộng mọi lõi có thể lớn hơn real ví dụ real 2s user 8s dùng khoảng 4 lõi trong 2 giây, quy trình 1 time ct xem tỉ lệ real user sys 2 real xấp xỉ user profiling CPU bài sau 3 real lớn hơn CPU strace đo I O tìm cái đang chờ

Hình 1: time cho real (đồng hồ tường), user (CPU chạy code bạn), sys (CPU trong kernel); ba dấu vân tay: user≈real = CPU-bound, real≫user+sys = đang chờ, sys cao = quá nhiều syscall.

Đo thật: ba chương trình, ba dấu vân tay

Mình chạy ba chương trình cùng "tốn thời gian" nhưng vì lý do khác nhau:

Ảnh chụp bảng kết quả chạy thật time trên 3 kiểu chương trình output thật, a CPU-bound 30 triệu vòng tính toán real 1.021s user 1.020s sys 0.001s user xấp xỉ real toàn bộ thời gian là CPU chạy code nghẽn ở thuật toán, b sleep-bound sleep 2s real 2.019s user 0.006s sys 0.003s real cao nhưng user cộng sys xấp xỉ 0 đang chờ không dùng CPU I O mạng DB khoá cũng cho dấu này, c syscall-heavy 500k lần write dev null real 0.094s user 0.041s sys 0.053s sys lớn hơn user phần lớn thời gian CPU nằm trong kernel syscall sửa giảm số syscall gom I O như bài strace -c, kết cùng chậm nhưng 3 nguyên nhân khác nhau cần 3 cách sửa khác nhau tỉ lệ real user sys chỉ đúng hướng chẩn đoán ngay lập tức

Hình 2: Chạy thật — (a) CPU-bound: real=1.021s user=1.020s (user≈real, nghẽn CPU); (b) sleep-bound: real=2.019s user=0.006s sys=0.003s (real≫CPU, đang chờ); (c) syscall-heavy: real=0.094s user=0.041s sys=0.053s (sys > user, nhiều syscall).

  • (a) CPU-bound — vòng lặp tính toán 30 triệu lần: user=1.020s ≈ real=1.021s, sys≈0. Toàn bộ thời gian là CPU chạy code của bạn. Nghẽn ở thuật toán → cần tối ưu code hoặc profiling CPU (bài sau) để tìm hàm nóng.
  • (b) sleep-bound — sleep 2s: real=2.019s nhưng user+sys ≈ 0. Chương trình chờ 2 giây mà không dùng CPU. Đây là dấu của đang chờ — I/O, mạng, database, khoá cũng cho dấu này. Sửa CPU vô ích; phải tìm cái gì đang chặn (strace, đo đĩa/DB).
  • (c) syscall-heavy — 500k lần write vào /dev/null: sys=0.053s > user=0.041s. Phần lớn CPU nằm trong kernel, làm syscall. Nghẽn ở số lượng syscall → giảm chúng (gom I/O), đúng như bài strace -c.

Cùng một triệu chứng "chậm", ba nguyên nhân, ba hướng sửa — và tỉ lệ real : user : sys chỉ đúng hướng ngay lập tức, trước khi bạn đào sâu.

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

real < user là bình thường trên đa lõi. Nếu chương trình chạy song song nhiều luồng trên nhiều lõi, user (cộng thời gian CPU của mọi lõi) có thể lớn hơn real. Ví dụ real=2s user=8s nghĩa là dùng khoảng 4 lõi trong 2 giây. Đây không phải lỗi — nó cho biết mức độ song song. Ngược lại, chương trình một luồng CPU-bound có user ≈ real (không tận dụng đa lõi — có thể là cơ hội tối ưu).

time là bước sàng lọc đầu, không phải câu trả lời cuối. Nó cho biết loại vấn đề (CPU/chờ/syscall) nhưng không cho biết chỗ nào trong code. Sau khi time chỉ ra CPU-bound, cần profiling CPU (perf/pprof) để tìm hàm nóng; chỉ ra đang chờ thì cần strace/đo I/O để tìm cái đang chặn. Dùng time để chọn công cụ đào sâu tiếp theo.

Phân biệt time builtin của shell và /usr/bin/time. Shell có time dựng sẵn (in real/user/sys cơ bản), còn /usr/bin/time -v (GNU) cho nhiều hơn: RSS đỉnh, số page fault, số lần chuyển ngữ cảnh — hữu ích để chẩn đoán sâu hơn. Nếu cần thông tin bộ nhớ/context switch cùng lúc, dùng /usr/bin/time -v.

Ba ý mang về

  1. real/user/sys phân loại "chậm": đo thật, CPU-bound cho user≈real (1.020≈1.021s), sleep-bound cho real≫user+sys (2.019 vs ~0), syscall-heavy cho sys>user (0.053 vs 0.041) — ba nguyên nhân khác nhau từ cùng triệu chứng.
  2. Tỉ lệ chỉ đúng hướng sửa: user≈real → tối ưu thuật toán/profiling CPU; real≫CPU → tìm cái đang chờ (I/O/mạng/khoá); sys cao → giảm syscall (gom I/O).
  3. time là bước sàng lọc: nó cho biết loại vấn đề chứ không chỗ nào trong code; real<user là bình thường trên đa lõi; dùng /usr/bin/time -v khi cần thêm RSS/page fault/context switch.

Nguồn

Phần sau ta dùng tín hiệu để debug: gửi SIGQUIT để một chương trình Go tự in stack tất cả goroutine, và core dump — ảnh chụp bộ nhớ lúc crash để mổ xẻ sau bằng gdb.