Tôi đoán hàm này ăn 70% CPU — chính tay tôi viết nó — hai phép đo nói 90,7% và 98,3%; và py-spy đo được điều đó gần như miễn phí

Có một sự thật khiêm nhường mà mọi lập trình viên phải học đi học lại: bạn không biết code của mình tiêu thời gian ở đâu, kể cả code bạn vừa gõ xong. Trực giác của ta ước lượng theo độ dài đoạn mã — hàm nào nhiều dòng thì chắc tốn nhiều thời gian. Nhưng máy tính không tính công theo số dòng; nó tính theo việc mỗi dòng thật sự làm, và một dòng băm 120 lần đắt gấp trăm lần cả một hàm mười dòng gọi thư viện chuẩn. Bài này là lần tôi cá cược vào trực giác của mình — về đoạn code chính tay tôi viết — và thua đậm, đo bằng con số.

Sê-ri đã đo log, chỉ số và trace — cả ba đều nói cho bạn biết cái gì chậm và ở đâu trong chuỗi dịch vụ. Không cái nào nói dòng mã nào. Đó là việc của hồ sơ, và câu hỏi thực dụng là: có thể bật nó suốt ngày ở môi trường chạy thật không, hay chỉ dùng được lúc gỡ lỗi? (Đo bằng py-spy và cProfile thật trong container; các con số là thời gian chạy, không phải perf counter phần cứng.)

Bảng số liệu

Một chương trình Python xử lý theo lô, có ba hàm trong đó một hàm nằm sâu trong ngăn xếp. Trung vị của ba lần chạy.

Con số −0,8% nằm trong nhiễu; thực tế là không đo được chi phí nào.

Và nó tìm ra gì:

Bốn điều đáng nhớ

Lấy mẫu ngoài tiến trình ở 99 Hz gần như miễn phí. Đó là toàn bộ lý do "hồ sơ liên tục" khả thi: bạn có thể để nó chạy suốt ngày trên máy chủ thật mà không phải cân nhắc gì.

cProfile làm chương trình chậm gấp 2,06 lần. Nó hữu ích trên máy phát triển và hoàn toàn không dùng được ở môi trường chạy thật — bật nó lên là tự tạo ra sự cố hiệu năng để đi điều tra sự cố hiệu năng.

Tăng tần số từ 99 lên 999 Hz đổi 5% hiệu năng lấy độ phân giải gấp mười. Hiếm khi đáng: 99 Hz đã đủ để chỉ ra thủ phạm trong bài này.

Và bài học lớn nhất không phải con số nào trong bảng. Khi viết chương trình thử nghiệm, tôi ghi thẳng vào chú thích rằng bam_cham chiếm khoảng 70% thời gian. Hai phép đo độc lập nói 90,7% và 98,3%. Tôi đoán sai, và tôi là người viết ra chính đoạn mã đó.

Vì sao chi phí hai bên khác hẳn

Khác biệt về chi phí đến từ chỗ bộ hồ sơ đứng.

cProfile chạy bên trong tiến trình, móc vào cơ chế theo dõi của Python và ghi lại mỗi lần vào và ra của mọi hàm. Với chương trình gọi hàm hàng triệu lần, đó là hàng triệu lần ghi sổ. Chi phí tỷ lệ với số lời gọi, nên chương trình nào càng chia nhỏ hàm thì càng bị phạt nặng.

py-spy chạy trong một tiến trình khác, dùng ptrace để đọc trực tiếp cấu trúc ngăn xếp của trình thông dịch trong bộ nhớ tiến trình mục tiêu. Tiến trình bị lấy mẫu không thực thi thêm một lệnh nào vì việc đó; nó chỉ bị tạm dừng vài micro-giây mỗi lần lấy mẫu. Chi phí tỷ lệ với tần số lấy mẫu, không tỷ lệ với việc chương trình làm gì. Đó là lý do 99 Hz gần như không đo được: chín mươi chín lần mỗi giây, mỗi lần vài micro-giây, là khoảng 0,1% thời gian.

Về chuyện tôi đoán sai: bam_cham chạy 120 vòng SHA-256, còn chuan_hoa và dong_goi gọi sorted() và .hex() trên 64 byte. Tôi nhìn thấy ba hàm với độ dài mã tương đương và ước lượng theo đó. Nhưng thời gian chạy không tỷ lệ với số dòng mã — nó tỷ lệ với việc mỗi dòng thực sự làm gì, và 120 lần băm là nhiều hơn hai lời gọi thư viện chuẩn tới hai bậc độ lớn.

Nghĩa là gì trong công việc hằng ngày

• Bật hồ sơ lấy mẫu ở môi trường chạy thật. Ở 99 Hz nó không tốn gì đo được, và nó là nguồn duy nhất trả lời được câu "dòng nào tốn CPU" mà không cần dựng lại sự cố.
• Đừng dùng bộ hồ sơ theo dõi từng lời gọi ở môi trường chạy thật. Gấp đôi thời gian chạy là mức phạt không thể chấp nhận, và tệ hơn là nó làm lệch chính kết quả: hàm nào bị gọi nhiều lần sẽ trông đắt hơn thực tế vì chi phí ghi sổ tính vào chúng.
• Bắt đầu từ 99 Hz. Chỉ tăng khi hồ sơ quá thưa để thấy được thứ bạn tìm — thường là khi hàm cần tìm chạy dưới vài chục mili-giây.
• Đừng tin ước lượng của chính mình về chỗ tốn thời gian, kể cả với mã bạn vừa viết. Đây là bài học tôi vừa học lại trong chính bài này.
• Kết hợp với các phần trước: trace chỉ ra dịch vụ nào, hồ sơ chỉ ra hàm nào bên trong dịch vụ đó. Hai thứ không thay thế nhau và cùng cần thiết để đi từ "chậm" tới "sửa chỗ này".

Có một hệ quả thực dụng của việc chi phí tỷ lệ với tần số chứ không tỷ lệ với chương trình: bạn biết trước hoá đơn. Với cProfile, mức phạt phụ thuộc vào việc mã của bạn gọi hàm nhiều hay ít, và bạn chỉ biết sau khi bật lên. Với lấy mẫu, 99 Hz là 99 Hz dù dịch vụ đang rảnh hay đang quá tải, dù mã có mười hàm hay mười nghìn. Điều đó cũng có nghĩa là hồ sơ lấy mẫu không làm sự cố nặng thêm — đúng lúc dịch vụ đang chật vật là lúc bạn cần nhìn vào nó nhất, và cũng là lúc mọi công cụ có chi phí tỷ lệ với tải sẽ đổ thêm dầu vào lửa.

Cùng một lằn ranh "sampling vs instrumenting", đổi ngăn xếp

Chuyện "lấy mẫu ngoài tiến trình gần như miễn phí, còn theo dõi từng lời gọi thì phạt nặng và làm lệch kết quả" không riêng gì Python — đây là hai trường phái profiler ở mọi nền tảng.

Trong thế giới Java, đúng lằn ranh này là async-profiler / JFR (Java Flight Recorder) lấy mẫu — dùng AsyncGetCallTrace và perf events, overhead vài phần trăm, bật được ở production — đối lại các profiler instrumenting cũ (chèn bytecode vào mọi method) làm chậm gấp bội và làm sai chính hình dạng hồ sơ (method inline bị chặn, JIT hành xử khác). Đó là lý do JFR được thiết kế để "always-on" trong production, đúng vai trò 99 Hz của py-spy ở đây.

Trong Go, pprof có sẵn trong stdlib và là lấy mẫu theo thiết kế: CPU profile lấy mẫu ngăn xếp ~100 Hz (đúng con số 99–100 Hz!), overhead nhỏ đủ để chạy liên tục — nền của cả một ngành "continuous profiling" (Pyroscope, Parca, Polar Signals) mà cộng đồng Go dẫn đầu chính vì pprof rẻ và có sẵn.

Còn ở cơ sở dữ liệu, cùng đánh đổi hiện ra giữa sampling trạng thái phiên (như pg_stat_activity / Active Session History của Oracle, lấy mẫu "phiên nào đang chạy gì" mỗi giây) và bật full statement logging (log_min_duration_statement = 0 ghi mọi câu — chính xác nhưng làm ngập I/O và chậm hệ khi tải cao). ASH là "py-spy của DBA": rẻ, always-on, đủ để chỉ ra câu query nóng.

Mẫu số chung: lấy mẫu định kỳ ngoài đường thực thi có chi phí tỷ lệ với tần số (nên biết trước và cố định), còn ghi lại mọi sự kiện có chi phí tỷ lệ với khối lượng công việc (nên nặng nhất đúng lúc tải cao và còn làm lệch kết quả về phía cái nó đếm nhiều). Vì thế công cụ an toàn để bật giữa lúc đang cháy luôn là loại lấy mẫu. Nên câu hỏi đúng khi chọn profiler không phải "cái nào chính xác nhất" mà là "chi phí của nó tỷ lệ với tần số tôi đặt hay với tải hệ thống" — vì chỉ loại thứ nhất mới dám bật lên khi bạn cần nó nhất.

Muốn tự thấy hai điều — chi phí gần bằng không và chỗ thời gian thật sự đi — chạy thử:

docker run --rm --cap-add SYS_PTRACE python:3.12-slim sh -c '
pip -q install py-spy
cat > /tmp/t.py <<EOF
import hashlib, time
def cham(d):
    h = d
    for _ in range(120): h = hashlib.sha256(h).digest()
    return h
def nhanh(d): return bytes(sorted(d))
def chay():
    lo = [bytes([i % 256]) * 64 for i in range(50)]
    for _ in range(400):
        for x in lo: nhanh(cham(x))
t = time.perf_counter(); chay()
print("chay het %.3f s" % (time.perf_counter() - t))
EOF
python3 /tmp/t.py                        # nen
python3 /tmp/t.py & PID=$!               # co lay mau
py-spy record -p $PID -r 99 -d 30 -f raw -o /tmp/r.txt >/dev/null 2>&1
wait $PID
awk "{n=\$NF; \$NF=\"\"; split(\$0,a,\";\"); s[a[length(a)]]+=n; t+=n}
     END{for(k in s) printf \"  %-30s %5.1f%%\n\", k, 100*s[k]/t}" /tmp/r.txt | sort -k2 -rn
'

So hai dòng chay het — chúng phải gần bằng nhau. Rồi nhìn bảng cuối: đó là chỗ chương trình của bạn thực sự tiêu thời gian, và nó thường không phải chỗ bạn nghĩ.