Cả loạt bài này đã đi từ triệu chứng ("chậm", "treo", "ngốn RAM") tới ngày càng gần nguyên nhân. Bài time (phần 6) cho biết chương trình nghẽn ở CPU hay ở chờ; nhưng khi đã biết là nghẽn CPU, câu hỏi tiếp theo là: hàm nào? — và đây là nơi nhiều người sai lầm nhất. Họ đoán: "chắc cái hàm parse JSON kia chậm", rồi bỏ cả ngày tối ưu nó, để rồi phát hiện thủ phạm thật là một vòng lặp tầm thường bị gọi hàng triệu lần. Profiling chấm dứt việc đoán mò. Bài này (phần 12, bài cuối loạt Debug) chạy thật một profiler để chỉ ra chính xác hàm — và cả dòng — đang ngốn CPU.

Profiler hoạt động thế nào

Ý tưởng của một CPU profiler kiểu lấy mẫu (sampling profiler) đơn giản đến bất ngờ: nó ngắt chương trình định kỳ (ví dụ ~100 lần mỗi giây) và mỗi lần ghi lại stack đang chạy là gì. Sau hàng nghìn lần lấy mẫu, hàm nào xuất hiện trong nhiều mẫu nhất chính là hàm đang chạy nhiều nhất — tức hàm nóng. Đây là suy luận thống kê: không đo từng lời gọi (tốn kém), mà lấy mẫu đủ nhiều để phân bố hiện ra.

Hai họ công cụ:

  • perf (Linux): profiler cấp hệ thống, đọc bộ đếm phần cứng (PMU) của CPU qua syscall perf_event_open. Mạnh, đo được cả kernel, nhưng cần quyền truy cập PMU.
  • Profiler user-space (Go pprof, py-spy...): lấy mẫu ở tầng ứng dụng (Go dùng tín hiệu SIGPROF của chính tiến trình), không cần quyền kernel — chạy được ở mọi nơi.

Ảnh chụp đoạn mã nền tối minh hoạ perf và profiling CPU tìm hàm nóng bằng số không đoán mò, vì sao profiling nhìn code không biết hàm nào ngốn CPU tối ưu bằng cảm giác thường sai chỗ đoán hàm A chậm tối ưu cả ngày hóa ra thủ phạm là hàm B profiler lấy mẫu stack định kỳ khoảng 100 lần một giây hàm nào xuất hiện nhiều bằng hàm đang chạy nhiều bằng nóng, ba hàm chi phí rất khác nhau hàm nào nóng hamNong O n bình phương hai vòng lồng nhau hamVua O n một vòng hamNhe O 1 return 42 nhân 42, bật CPU profile bằng runtime pprof không cần quyền kernel os Create cpu prof pprof StartCPUProfile bắt đầu lấy mẫu stack defer StopCPUProfile chạy tải thật go build rồi chạy go tool pprof -top liệt kê hàm theo phần trăm CPU go tool pprof -list hamNong chỉ ra dòng nóng nhất, vì sao pprof không phải perf trong container này perf cần đọc bộ đếm phần cứng PMU qua perf_event_open container Docker Desktop không được cấp quyền đó pprof lấy mẫu ở tầng user-space tín hiệu SIGPROF của chính tiến trình nên chạy được ở mọi nơi

Hình 1: Profiler lấy mẫu stack định kỳ để tìm hàm nóng; ba hàm (hamNong O(n²), hamVua O(n), hamNhe O(1)) khó đoán bằng mắt; bật CPU profile bằng runtime/pprof (StartCPUProfile), rồi go tool pprof -top/-list; pprof chạy user-space nên không cần quyền PMU như perf.

Thử perf thật — và bị container chặn (báo trung thực)

Trước hết mình thử perf trong go-lab, cài nó bằng apt-get install linux-perf. Cài được, nhưng khi chạy thì:

$ perf stat /bin/true
Error: No permission to enable task-clock event.
$ perf record /bin/true
perf_event_open(...) failed unexpectedly with error 1 (Operation not permitted)

Đây là kết quả thật, và nó là một bài học thật: perf cần đọc perf_event của kernel, mà container Docker Desktop không được cấp quyền đó (máy chủ chạy trong một VM Linux nhẹ, không expose PMU cho container). Trên một máy chủ Linux thật (bare-metal hoặc VM có quyền), perf chạy tốt và là công cụ hàng đầu; nhưng ở đây mình không thể demo nó — nên nói thẳng thay vì bịa ra output. May thay, có phương án user-space không cần quyền kernel: Go pprof.

Đo thật: pprof chỉ đúng hàm nóng và dòng nóng

Mình viết một chương trình Go có ba hàm chi phí rất khác nhau: hamNong (hai vòng lặp lồng nhau, O(n²)), hamVua (một vòng, O(n)), và hamNhe (O(1), gần như không làm gì). Bật CPU profile bằng pprof.StartCPUProfile, chạy tải, rồi phân tích:

Ảnh chụp bảng kết quả chạy thật profiling pprof output thật go-lab runtime pprof perf event open bị chặn, một perf thử thật bị kernel container từ chối báo trung thực perf stat bin true Error No permission to enable task-clock event perf record bin true perf_event_open failed unexpectedly with error 1 Operation not permitted Docker Desktop không cấp PMU perf_event nên perf vô dụng ở đây dùng Go pprof user-space không cần quyền kernel, hai go tool pprof -top xếp hạng hàm theo phần trăm CPU mẫu thật Duration 1.15s Total samples 950ms 82.41 phần trăm flat flat phần trăm sum phần trăm cum cum phần trăm 720ms 75.79 phần trăm main hamNong inline 230ms 24.21 phần trăm main hamVua inline 0 phần trăm main main 0 phần trăm runtime main hamNong bằng 75.79 phần trăm CPU hamVua 24.21 phần trăm hamNhe không xuất hiện khoảng 0 phần trăm số thật trả lời tối ưu hamNong trước đừng đụng vào hamNhe, ba pprof -list hamNong chỉ đúng dòng ngốn CPU ROUTINE main hamNong 720ms 720ms flat cum 75.79 phần trăm of Total 10ms dòng 16 for j nhỏ hơn n 710ms dòng 17 tong cộng i xor j and 0xff dòng nóng dòng 18 dòng 17 thân vòng lặp trong ăn 710 trên 720ms của hàm biết chính xác dòng nào để tối ưu không phải cả hàm

Hình 2: Chạy thật — perf bị chặn (perf_event_open ... Operation not permitted); go tool pprof -top cho main.hamNong 75.79% (720ms), main.hamVua 24.21% (230ms), hamNhe không xuất hiện; pprof -list=hamNong chỉ đúng dòng 17 ăn 710/720ms.

  • pprof -top xếp hạng hàm theo % CPU: trên 950ms mẫu thu được, main.hamNong chiếm 75.79% (720ms), main.hamVua 24.21% (230ms), còn hamNhe không xuất hiện — nó quá nhẹ để lọt vào một mẫu nào. Con số thật trả lời dứt khoát: muốn nhanh hơn thì tối ưu hamNong, và đừng phí công vào hamNhe.
  • Cột flat vs cum: flat là thời gian trong chính hàm đó; cum (cumulative) gồm cả các hàm nó gọi. main.main có flat=0 nhưng cum=100% — nó không tự làm gì nặng, chỉ gọi các hàm nặng. Đây là cách đọc để phân biệt "hàm tự nó nóng" với "hàm gọi thứ nóng".
  • pprof -list chỉ đúng dòng: đây là điều khiến profiling mạnh hơn hẳn đoán mò. go tool pprof -list=hamNong in mã nguồn kèm thời gian từng dòng: dòng 17 (tong += (i ^ j) & 0xff, thân vòng lặp trong) ăn 710/720ms của cả hàm. Bạn không chỉ biết hàm nào, mà biết dòng nào — tối ưu đúng chỗ, không mò cả hàm.

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

Sampling profiler cần đủ mẫu mới đáng tin. Con số 75.79% đến từ 950ms mẫu; nếu chỉ chạy 50ms thì vài mẫu lẻ không phản ánh đúng phân bố. Chạy tải đủ lâu (hoặc đủ lặp) để profiler thu hàng nghìn mẫu — với tải quá ngắn, hãy tăng vòng lặp hoặc dùng benchmark (go test -bench -cpuprofile). Ngược lại, lấy mẫu quá dày làm chậm chính chương trình đang đo.

Profile CPU không thấy thời gian chờ. CPU profiler chỉ đếm khi chương trình đang chạy trên CPU. Một hàm ngồi chờ I/O, chờ khoá, hay sleep sẽ không hiện nóng trong CPU profile — dù nó làm chương trình chậm (nhớ bài time: real ≫ CPU). Với loại chậm "đang chờ", cần block profile / trace (runtime/trace, -blockprofile) chứ không phải CPU profile. Chọn đúng loại profile theo triệu chứng.

perf mạnh hơn ở chỗ pprof không với tới — khi có quyền. Trên máy chủ Linux thật, perf thấy được cả kernel, cả các tiến trình khác, và các sự kiện phần cứng (cache miss, branch misprediction) mà profiler user-space không đo được. pprof tuyệt cho code Go của bạn; perf cho toàn hệ thống và phần cứng. Ở container này pprof là lựa chọn khả thi, nhưng đừng quên perf khi bạn có một máy chủ thật để chẩn đoán sâu.

Ba ý mang về

  1. Profiling thay đoán mò bằng số: đo thật go tool pprof -top cho hamNong 75.79% CPU, hamVua 24.21%, hamNhe ~0% (không xuất hiện) — profiler lấy mẫu stack định kỳ để chỉ ra hàm thực sự nóng, thay vì tối ưu theo cảm giác.
  2. -list chỉ tới tận dòng, flat vs cum phân biệt tự-nóng và gọi-thứ-nóng: đo thật dòng 17 ăn 710/720ms của hamNong; main.main có cum=100% nhưng flat=0 vì chỉ gọi chứ không tự làm nặng.
  3. Chọn đúng công cụ: perf bị chặn trong container này (perf_event_open ... Operation not permitted — báo trung thực) nên dùng Go pprof user-space; nhớ CPU profile không thấy thời gian chờ (cần block/trace profile), và perf mới thấy kernel + phần cứng khi bạn có máy chủ thật.

Tổng kết loạt "Debug và hiệu năng Linux" (12 phần)

Loạt bài này đi trọn một hành trình chẩn đoán, từ một syscall tới một dòng code nóng:

  • Phần 1-2 — strace, ltrace: xem chương trình nói chuyện với kernel (syscall) và với thư viện (lời gọi hàm) — tìm ra nó đang mở file gì, gọi gì, hỏng ở đâu.
  • Phần 3-4 — /proc/<pid>/fd, /proc/<pid>/maps: soi file descriptor (bắt rò rỉ fd) và bản đồ bộ nhớ của tiến trình.
  • Phần 5 — RSS vs VSZ: đọc đúng con số bộ nhớ, phân biệt bộ nhớ ảo đặt chỗ với RAM thật.
  • Phần 6 — time (real/user/sys): phân loại "chậm" thành CPU-bound, đang-chờ, hay syscall-heavy.
  • Phần 7 — tín hiệu & core dump: ép chương trình treo tự khai stack (SIGQUIT), mổ xẻ crash.
  • Phần 8 — top/ps: tìm tiến trình ngốn CPU/RAM ở cấp hệ thống.
  • Phần 9 — /proc/<pid>/io: đo I/O thật của tiến trình, tránh bẫy page cache.
  • Phần 10 — load average: hiểu ba số 1/5/15 phút, và vì sao load cao chưa chắc CPU nghẽn.
  • Phần 11 — latency & percentile: vì sao mean giấu đuôi, và p99 mới nói lên trải nghiệm.
  • Phần 12 — profiling: tìm đúng hàm và dòng nóng bằng số.

Điểm chung xuyên suốt: đừng đoán — đo. Mỗi công cụ trả lời một câu hỏi cụ thể, và biết chọn công cụ theo triệu chứng là kỹ năng phân biệt người sửa bug nhanh với người mò mẫm. Chúc bạn debug vui, và luôn có số liệu thật trong tay.

Nguồn