Có một câu nói kinh điển trong tối ưu hiệu năng: "đừng đoán, hãy đo". Lý do là trực giác của lập trình viên về chỗ nào chậm gần như luôn sai — bạn dành cả buổi tối ưu một hàm mà hoá ra nó chỉ chiếm 2% thời gian, trong khi thủ phạm thật nằm ở một chỗ chẳng ai ngờ. Phần 7 (tracing) cho biết chặng nào của request chậm, nhưng bên trong một chặng — một hàm xử lý — thì hàm con nào ngốn CPU, dòng nào cấp phát bộ nhớ nhiều nhất? Đó là việc của profiling.

Go có một trong những bộ profiler tốt nhất tích hợp sẵn: pprof. Nó không phải công cụ ngoài — gói runtime/pprof nằm trong thư viện chuẩn, và go tool pprof đi kèm mọi bản cài Go. pprof lấy mẫu chương trình đang chạy và cho biết chính xác hàm nào tiêu tốn CPU (CPU profile) hay giữ bộ nhớ (heap profile). Bài này (phần 8 loạt Observability) chạy thật cả hai loại profile và — quan trọng không kém — giải thích cách đọc chúng, vì hiểu sai hai cột flat/cum là nhầm thủ phạm.

Cơ chế: lấy mẫu CPU và chụp heap

CPU profile hoạt động bằng sampling: khoảng 100 lần/giây, runtime dừng chương trình một chớp và ghi lại stack đang chạy. Sau vài giây, hàm nào xuất hiện trong nhiều mẫu nhất chính là hàm ngốn CPU nhất. Vì chỉ lấy mẫu (không đo từng lời gọi), chi phí rất nhẹ — đủ nhẹ để chạy cả trên production.

Heap profile thì khác: nó chụp ảnh tức thời của bộ nhớ đang được cấp phát, cho biết hàm nào đã cấp phát (và đang giữ) bao nhiêu bộ nhớ.

Ảnh chụp đoạn mã nền tối minh hoạ pprof tìm hàm nóng CPU và điểm ngốn bộ nhớ, khối CPU profile chụp bằng runtime pprof cf os.Create cpu.prof pprof.StartCPUProfile cf bắt đầu lấy mẫu 100Hz gọi hotHash hàm nặng băm SHA256 4 triệu lần rồi lightWork hàm nhẹ pprof.StopCPUProfile go tool pprof -top đọc file, khối Heap profile chụp sau runtime.GC var kept slice byte hàm allocBig lặp 200 lần append kept make byte 1 dịch trái 20 giữ 200 nhân 1MB runtime.GC dọn rác trước khi chụp inuse pprof.WriteHeapProfile hf thấy hàm giữ nhiều RAM nhất, khối flat vs cum hai cột phải đọc khác nhau flat là thời gian bộ nhớ trong chính hàm đó cum gồm cả các hàm con nó gọi một hàm có cum cao mà flat thấp nghĩa là chậm vì gọi thứ khác chậm không phải bản thân nó nặng

Hình 1: CPU profile — pprof.StartCPUProfile/StopCPUProfile bọc quanh đoạn cần đo (lấy mẫu 100Hz). Heap profile — runtime.GC() rồi pprof.WriteHeapProfile để chụp bộ nhớ đang giữ. Và điểm dễ nhầm: flat là chi phí trong chính hàm, cum gồm cả hàm con nó gọi.

Đo thật trong go-lab

Mình viết trong go-lab (golang 1.23) một chương trình có: một hàm CPU-nặng cố ý (hotHash — băm SHA256 bốn triệu lần) cạnh một hàm nhẹ (lightWork); và một hàm giữ nhiều bộ nhớ (allocBig — giữ 200 slice 1MB = 200MB) cạnh một hàm cấp phát rồi bỏ (allocSmall). Rồi chụp cả hai profile và đọc bằng go tool pprof -top.

Ảnh chụp bảng kết quả chạy thật go tool pprof -top output thật golang 1.23 runtime pprof thư viện chuẩn, khối một CPU profile hàm nóng chiếm phần lớn CPU cột flat flat phần trăm cum cum phần trăm 50ms 29.4 phần trăm 130ms 76.5 phần trăm crypto sha256.Sum256 50ms 29.4 phần trăm 50ms 29.4 phần trăm crypto sha256.sha256block 40ms 23.5 phần trăm 170ms 100 phần trăm main.hotHash 10ms 5.9 phần trăm 70ms 41.2 phần trăm sha256 digest checkSum main.lightWork không xuất hiện quá nhẹ chú thích main.hotHash cum bằng 100 phần trăm toàn bộ CPU đi qua nó flat chỉ 40ms vì phần nặng nằm ở sha256 nó gọi tối ưu giảm số lần băm, khối hai Heap profile hàm giữ nhiều RAM nhất inuse_space 197.76MB 100 phần trăm 197.76MB 100 phần trăm main.allocBig 0 0 phần trăm 197.76MB 100 phần trăm main.main main.allocSmall không xuất hiện 1KB không giữ đã GC chú thích main.allocBig giữ đúng khoảng 200MB 200 nhân 1MB sau runtime.GC đang thật sự chiếm RAM allocSmall biến mất vì không giữ tham chiếu GC thu hồi đây là cách bắt rò rỉ hàm nào giữ RAM lâu

Hình 2: Kết quả thật — CPU profile: main.hotHash cum 100% (flat 40ms), sha256.Sum256 cum 76.5%, lightWork không xuất hiện; heap profile: main.allocBig giữ 197.76MB (100%), allocSmall biến mất vì đã bị GC.

Đọc kết quả:

  • CPU: hàm nóng lộ ngay. main.hotHash có cum=100% — toàn bộ thời gian CPU đi qua nó. Đáng chú ý là flat của nó chỉ 40ms (23.5%), trong khi sha256.Sum256 có flat 50ms và cum 76.5%. Điều này nói: hotHash không tự nó nặng, mà nặng vì gọi sha256 nhiều. Và main.lightWork không xuất hiện — nó quá nhẹ, không lọt vào mẫu nào. Đây chính là "đừng đoán, hãy đo" trong hành động: profile chỉ thẳng chỗ đáng tối ưu (giảm số lần băm) và loại chỗ không đáng (lightWork).
  • Heap: hàm giữ RAM lộ ngay. main.allocBig chiếm 197.76MB = 100% bộ nhớ đang giữ (đúng 200 × 1MB). Còn allocSmall — cấp phát 1KB nhưng không giữ tham chiếu — không xuất hiện, vì đã bị GC thu hồi trước khi chụp (mình gọi runtime.GC() trước). Đây là cách bắt rò rỉ bộ nhớ: chụp heap sau GC, hàm nào vẫn giữ nhiều RAM là hàm đáng nghi.
  • flat vs cum là chìa khoá đọc đúng. flat = chi phí trong chính hàm (không tính hàm con). cum = gồm cả hàm con. Nhìn cum để biết "toàn bộ nhánh này tốn bao nhiêu"; nhìn flat để biết "hàm nào tự nó tốn". Nhầm hai cột dẫn tới tối ưu sai chỗ — ví dụ thấy main.hotHash cum 100% mà lao vào tối ưu code trong nó thì vô ích, vì flat chỉ 40ms; chỗ thật sự tốn là sha256.

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

CPU profile là sampling — hàm siêu ngắn có thể lọt. Vì chỉ lấy mẫu ~100 lần/giây, một hàm chạy rất nhanh nhưng gọi cực nhiều lần có thể bị đánh giá thấp, hoặc một hàm ngắn tình cờ không rơi vào mẫu nào (như lightWork biến mất). Sampling đánh đổi độ chính xác tuyệt đối lấy chi phí thấp — nó rất tốt để tìm hàm nóng lớn, nhưng đừng tin nó tới từng phần trăm cho các hàm nhỏ. Với đo chính xác từng lời gọi cần công cụ khác (tracing/benchmark), nhưng cho 90% trường hợp "tìm thủ phạm chính", sampling là đủ và đúng.

Phải profile khi tải THẬT — profile lúc rảnh là vô nghĩa. Đây là sai lầm phổ biến: profile một chương trình đang không làm gì, rồi kết luận. CPU profile chỉ có ý nghĩa khi chương trình đang chịu tải giống production — vì hàm nóng lúc tải cao có thể hoàn toàn khác lúc rảnh. Với dịch vụ đang chạy, dùng net/http/pprof: import nó là có ngay endpoint /debug/pprof/ để thu profile của tiến trình đang phục vụ thật, không cần dừng hay build lại. (Và như mọi endpoint debug — /debug/vars, /metrics — phải bảo vệ nó, đừng hở ra Internet.)

Heap profile: phân biệt inuse và alloc. Mặc định go tool pprof xem inuse_space — bộ nhớ đang giữ tại lúc chụp (tốt để tìm rò rỉ, như demo). Nhưng có loại khác alloc_space — tổng bộ nhớ đã từng cấp phát (kể cả đã giải phóng). Hai câu hỏi khác nhau: "cái gì đang giữ RAM?" (inuse — tìm rò rỉ) vs "cái gì tạo áp lực GC bằng cách cấp phát liên tục?" (alloc — tìm chỗ cấp phát nóng gây GC nhiều). Dùng -sample_index=alloc_space khi điều tra GC, inuse_space khi điều tra rò rỉ. Chọn nhầm là trả lời nhầm câu hỏi.

Ba ý mang về

  1. Đừng đoán hàm nào chậm — pprof đo trực tiếp: đo thật, CPU profile chỉ main.hotHash cum 100% (và lightWork biến mất vì quá nhẹ), heap profile chỉ main.allocBig giữ 197.76MB (và allocSmall biến mất vì đã GC) — profiler loại bỏ phỏng đoán, chỉ thẳng chỗ đáng tối ưu.
  2. flat vs cum phải đọc đúng kẻo tối ưu nhầm chỗ: flat là chi phí trong chính hàm, cum gồm cả hàm con; hotHash cum 100% nhưng flat chỉ 40ms — chỗ nặng thật là sha256 nó gọi, không phải code trong hotHash.
  3. pprof là sampling, cần đúng bối cảnh: CPU profile nhẹ nhờ lấy mẫu 100Hz nhưng hàm siêu ngắn có thể lọt; phải profile khi tải thật (dùng net/http/pprof cho tiến trình production, và bảo vệ endpoint); heap phân biệt inuse_space (tìm rò rỉ) và alloc_space (tìm áp lực GC).

Nguồn

Phần sau ta quan sát chính runtime Go từ bên trong: gói runtime/metrics cho biết số goroutine, kích thước heap, số lần và thời gian GC — những chỉ số sức khoẻ nội tại mà mọi dịch vụ Go nên expose.