Off-CPU và Độ Trễ Scheduler: Đo Thời Gian Tiến Trình KHÔNG Chạy

Profiling on-CPU (Bài 17) trả lời "CPU bận làm gì". Nhưng một ứng dụng chậm thường không vì CPU cháy — mà vì nó ngồi chờ: chờ đĩa, chờ mạng, chờ một khóa, hoặc chờ tới lượt được cấp CPU. Thời gian đó là off-CPU, và profiling on-CPU không thấy gì (tiến trình có chạy đâu mà lấy mẫu). Bài này đo đúng khoảng trống đó, qua các tracepoint của bộ lập lịch.

Hai câu hỏi off-CPU khác nhau

"Off-CPU" gộp hai thứ nên tách rõ:

Run-queue latency — tác vụ đã sẵn sàng chạy (được đánh thức) rồi, nhưng phải chờ một lõi CPU rảnh. Đây là độ trễ do scheduler/tranh CPU, không phải do tác vụ tự chờ gì.
Off-CPU time — tác vụ tự nhường CPU để chờ một sự kiện (I/O xong, khóa được nhả, hết sleep). Đây là thời gian bị chặn.

Cả hai đọc từ các tracepoint scheduler: sched_wakeup (một tác vụ trở nên sẵn sàng) và sched_switch (CPU chuyển từ tác vụ này sang tác vụ khác).

Run-queue latency: chờ tới lượt CPU

Đo khoảng từ lúc đánh thức (sched_wakeup) tới lúc thật sự được chạy (sched_switch chọn nó làm next):

sudo bpftrace -e '
tracepoint:sched:sched_wakeup     { @qt[args.pid] = nsecs; }
tracepoint:sched:sched_wakeup_new { @qt[args.pid] = nsecs; }
tracepoint:sched:sched_switch /@qt[args.next_pid]/ {
  @runq_us = hist((nsecs - @qt[args.next_pid]) / 1000);   // micro-giây
  delete(@qt[args.next_pid]);
}'

sched_wakeup ghi timestamp khóa theo pid (tác vụ được đánh thức); khi sched_switch chọn đúng pid đó làm tác vụ kế (next_pid), hiệu hai mốc là thời gian chờ trong hàng đợi chạy. Tạo áp lực lịch (4 tác vụ bận trên 2 CPU) rồi đo:

@runq_us:
[1]                 1428 |@@@@@@@@@@@@                                        |
[2, 4)              1692 |@@@@@@@@@@@@@@@                                     |
[4, 8)              5787 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[8, 16)              919 |@@@@@@@@                                            |
[16, 32)             355 |@@@                                                 |
...
[2K, 4K)              10 |                                                    |
[16K, 32K)             2 |                                                    |

Đơn vị micro-giây. Phần lớn tác vụ lên CPU sau 4-8µs — nhanh. Nhưng có cái đuôi ra tới [16K, 32K): vài lần phải chờ 16-32ms mới được chạy. Đó chính là dấu hiệu tranh CPU — nhiều tác vụ sẵn sàng hơn số lõi, vài tác vụ phải xếp hàng lâu. Trên một node bị quá tải CPU, cái đuôi này là thứ làm ứng dụng giật mà profiling on-CPU không bao giờ chỉ ra. Đây đúng là công cụ runqlat của BCC, dựng bằng vài dòng.

Off-CPU time: bị chặn bao lâu

Câu hỏi khác: mỗi lần rời CPU, tác vụ nằm ngoài bao lâu? Ghi mốc lúc bị chuyển ra (prev_pid), tính hiệu lúc quay lại (next_pid):

sudo bpftrace -e '
tracepoint:sched:sched_switch {
  @off[args.prev_pid] = nsecs;                         // vừa rời CPU
  $t = @off[args.next_pid];
  if ($t) { @offcpu_ms = hist((nsecs - $t) / 1000000); delete(@off[args.next_pid]); }
}'

@offcpu_ms:
[0]                22137 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[1]                 3005 |@@@@@@@                                             |
[8, 16)             1248 |@@                                                  |
[64, 128)            431 |@                                                   |
[256, 512)           291 |                                                    |
[512, 1K)            180 |                                                    |
[4K, 8K)               4 |                                                    |

Đơn vị mili-giây. Phần lớn khoảng off-CPU dưới 1ms (chuyển ngữ cảnh thường), nhưng đuôi kéo tới [4K, 8K) — 4 đến 8 giây off-CPU. Đó là các tác vụ bị chặn lâu: daemon ngủ chờ sự kiện, tiến trình chờ I/O, sleep trong vòng lặp. Cái đuôi này là thời gian thực mà người dùng cảm nhận như "chậm/treo", và nó vô hình với profiling on-CPU — tác vụ có chạy đâu mà lấy mẫu được.

Lưu ý đọc số: bucket [0] áp đảo vì hầu hết chuyển ngữ cảnh là chớp nhoáng; cái đuôi mới là phần đáng soi. Muốn biết tác vụ bị chặn ở đâu trong nhân, đổi khóa từ pid sang kstack lúc bị chuyển ra — sẽ ra off-CPU theo stack, ghép với on-CPU thành bức tranh đầy đủ.

Vì sao đo được trong nhân mà không tốn

Cả hai phép đo chỉ gắn vào tracepoint scheduler — những điểm nhân vốn đã chạy mỗi lần chuyển ngữ cảnh. Chương trình eBPF chỉ ghi một timestamp vào map và cộng vào histogram; không bơm sự kiện nào ra userspace. Scheduler là đường cực nóng (hàng trăm nghìn lần/giây), nhưng vì gộp ngay trong nhân (Bài 7), chi phí thêm là không đáng kể — nên đo được cả trên production.

🧹 Dọn dẹp

bpftrace tự gỡ khi thoát; node về 140 chương trình. Lệnh ở github.com/nghiadaulau/ebpf-from-scratch, thư mục 18-off-cpu.

Tổng kết

Phần lớn độ trễ nằm ở lúc tiến trình không chạy — thứ profiling on-CPU (Bài 17) không thấy. eBPF đo off-CPU qua tracepoint scheduler. Run-queue latency (sched_wakeup → sched_switch chọn next_pid) là thời gian chờ tới lượt CPU: dưới tải tranh chấp, phần lớn 4-8µs nhưng đuôi tới 16-32ms — dấu hiệu thiếu CPU. Off-CPU time (sched_switch: mốc lúc prev ra, hiệu lúc next vào) là thời gian bị chặn: phần lớn dưới 1ms nhưng đuôi tới vài giây cho tác vụ chờ I/O/khóa/sleep. Cả hai gộp histogram trong nhân (runqlat/offcputime của BCC), gần như không nhiễu vì chỉ thêm việc vào tracepoint scheduler vốn đã chạy. On-CPU (Bài 17) + off-CPU (bài này) = bức tranh hiệu năng đầy đủ: CPU cháy ở đâu, và thời gian chờ đi đâu.

Bài 19 khép Part VI bằng cách hệ Kubernetes biến tất cả những sự kiện eBPF này thành thứ quan sát được toàn cụm: Hubble — mổ cách Cilium đẩy sự kiện từ datapath eBPF (qua perf/ring buffer cilium_events) lên thành bức tranh luồng mạng có nhãn pod, service, verdict policy.