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?

Hồ sơ liên tục: giá bao nhiêu, tìm ra được gì

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.

Cách lấy hồ sơ Thời gian chạy So với nền
Không lấy hồ sơ 0,262 s —
py-spy, lấy mẫu 99 Hz 0,260 s −0,8%
py-spy, lấy mẫu 999 Hz 0,275 s +5,0%
cProfile 0,541 s +106%

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ì:

bam_cham chuan_hoa dong_goi
Tôi đoán, khi viết mã ~70% ~15% ~15%
py-spy báo 98,3% — —
Đo trực tiếp, chạy riêng từng hàm 90,7% 5,0% 4,4%

Đ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

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 thực tế

  • 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. Bộ hồ sơ lấy mẫu ngoài tiến trình là một trong số ít công cụ an toàn để bật giữa lúc đang cháy.

Chỗ tôi không kết luận được

Hai phép đo về bam_cham lệch nhau 7,6 điểm phần trăm — 90,7% khi đo trực tiếp so với 98,3% khi lấy mẫu — và tôi không chốt được cái nào đúng hơn.

Phép đo trực tiếp của tôi có khiếm khuyết rõ: tôi tính phần của chuan_hoa bằng cách đo sorted(bam(x)) rồi trừ đi thời gian của bam(x), nên nó gánh thêm chi phí của một lambda và một lời gọi hàm phụ. Điều đó làm hai hàm nhỏ trông đắt hơn thực tế, tức kéo tỷ lệ của bam_cham xuống.

Còn py-spy quy chi phí của hàm C vào khung Python gọi nó — sorted() và .hex() là hàm dựng sẵn viết bằng C, nên thời gian trong đó được tính cho chuan_hoa và dong_goi, đúng như mong muốn. Nhưng SHA-256 cũng là C, và nó được tính cho bam_cham.

Cái tôi tin: thủ phạm là bam_cham, và nó chiếm 90% trở lên. Con số chính xác thì tôi không có. Điều quan trọng là cả hai cách đo đều bác bỏ ước lượng 70% của tôi theo cùng một hướng.

Đây là Python và py-spy. Bộ hồ sơ lấy mẫu cho ngôn ngữ biên dịch — perf trên Linux, hay pprof cho Go — có cơ chế khác và chi phí khác. Nguyên tắc "lấy mẫu ngoài tiến trình rẻ, theo dõi từng lời gọi đắt" thì giữ nguyên.

Tôi chỉ đo hồ sơ CPU. Hồ sơ bộ nhớ, hồ sơ khoá, hồ sơ tranh chấp đều có chi phí riêng và thường cao hơn, vì chúng không lấy mẫu được theo cách đơn giản như CPU.

Chương trình thử của tôi chạy trong 0,26 giây và chỉ có một luồng. Tiến trình dài chạy nhiều luồng làm py-spy phải đọc nhiều ngăn xếp mỗi lần lấy mẫu, và chi phí tăng theo số luồng — một chiều tôi không đo.

Thử ba mươi giây

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ĩ.