Thực hành: tìm chỗ chậm trong pipeline Python của khách bằng cProfile và py-spy

Job chạy đêm của khách trước đây mất 20 phút, giờ chạy ba tiếng vẫn chưa xong. Ai trong phòng họp cũng có giả thuyết riêng: do database, do mạng, do thư viện mới nâng cấp. Một FDE giỏi không góp thêm giả thuyết nào. Họ chạy profiler, và mười phút sau đã chỉ ra đúng hàm đang ngốn thời gian.

Kỹ năng này nghe thì cơ bản, nhưng ở chỗ khách, nó quyết định bạn có giữ được lòng tin hay không. Bạn thường không được sửa code tùy ý, không được khởi động lại service đang chạy, và còn phải giải thích kết quả cho những người không viết dòng code nào trong đó.

Bài này đi qua hai công cụ cho hai tình huống ấy: cProfile khi bạn chạy lại được script, py-spy khi tiến trình đã chạy sẵn trên máy khách.

Bạn sẽ làm gì, cần chuẩn bị gì?

Bạn sẽ profile một pipeline giả lập được viết chậm có chủ đích, đọc kết quả, sửa rồi đo lại. Bạn cần Python 3, một terminal và py-spy, cài theo hướng dẫn trong repo benfred/py-spy trên GitHub. Phần Docker cần máy đã cài Docker.

Dưới đây là script mẫu. Nó mô phỏng một bước enrich rất hay gặp: ghép mỗi dòng giao dịch với thông tin khách hàng.

# slow.py — pipeline giả lập, cố tình chậm
def load_rows(n):
    return [{"id": i, "customer": i % 1000} for i in range(n)]

def enrich(rows, customers):
    out = []
    for r in rows:
        # tìm tuyến tính trong list cho MỖI dòng
        match = [c for c in customers if c["id"] == r["customer"]]
        out.append({**r, "name": match[0]["name"]})
    return out

def main():
    customers = [{"id": i, "name": f"kh{i}"} for i in range(1000)]
    rows = load_rows(50_000)
    enrich(rows, customers)

if __name__ == "__main__":
    main()

Bước 1: chạy cProfile và sắp theo cumulative

cProfile là profiler tất định: nó theo dõi mọi sự kiện gọi hàm, trả về và exception, rồi đo chính xác khoảng thời gian giữa các sự kiện đó. Trên các bản Python mới, tài liệu gọi profiler này là profiling.tracing và giữ cProfile làm alias tương thích ngược, nên lệnh quen thuộc vẫn chạy được.

python -m cProfile -s cumulative slow.py

Kiểm tra: ở đầu bảng, main và enrich có cumulative time gần bằng tổng thời gian chạy. Tài liệu Python khuyên dùng đúng cột này để tìm lỗi chọn thuật toán ở mức cao. Ở đây lỗi lộ ra ngay: enrich gánh gần hết thời gian, trong khi việc nó làm chỉ là tra cứu.

Bước 2: đổi sang time để tìm vòng lặp nóng

python -m cProfile -s time slow.py

Cột time là thời gian nội tại, tức thời gian nằm trong chính hàm đó, không tính các hàm con. Theo tài liệu Python, đây là con số dùng để tìm “hot loop” cần tối ưu kỹ. Đọc code của script mẫu là thấy vì sao: mỗi dòng trong 50.000 dòng đều quét qua cả 1.000 khách hàng.

Tùy phiên bản Python bạn dùng, list comprehension bên trong enrich có thể hiện thành một dòng riêng trong bảng, cũng có thể không. Dù thế nào, chi phí quét danh sách vẫn nằm quanh enrich, nên hãy tìm ở đó.

Thứ tự đọc ở đây rất quan trọng. Đọc cumulative trước để trả lời câu hỏi “có đang chọn sai cách làm không”, rồi đọc time để biết “vòng lặp nào cần vắt từng mili giây”. Tối ưu vòng lặp bên trong một thuật toán sai là cách phí thời gian nhanh nhất.

Cách sửa đơn giản là dựng một dict một lần rồi tra cứu trong đó:

def enrich(rows, customers):
    by_id = {c["id"]: c["name"] for c in customers}
    return [{**r, "name": by_id[r["customer"]]} for r in rows]

Chạy lại bước 1 rồi so cumulative time của enrich trước và sau khi sửa. Hãy nhìn con số tuyệt đối chứ đừng nhìn thứ hạng: enrich vẫn có thể đứng gần đầu bảng, ngay dưới main, vì nó vẫn là bước nặng nhất của một script nhỏ như thế này.

Bước 3: lưu kết quả ra file để so sánh

Khi cần gửi kết quả cho đồng nghiệp hoặc so sánh trước và sau, hãy ghi ra file bằng -o, rồi đọc file đó bằng module pstats trong thư viện chuẩn.

python -m cProfile -o before.prof slow.py

Lỗi hay gặp: thêm -s cumulative vào lệnh có -o rồi thắc mắc vì sao không thấy bảng. Tài liệu ghi rõ khóa sắp xếp chỉ có tác dụng khi không dùng -o. Các khóa hợp lệ gồm cumulative, time, calls và name.

Một lỗi khác: báo cho khách số giây đo được dưới cProfile như thể đó là thời gian chạy thật. Vì phải ghi lại mọi sự kiện, profiler này làm chương trình chạy chậm đi. Hãy dùng nó để so tỷ lệ giữa các hàm, còn thời gian thật thì đo riêng, lúc không bật profiler.

Bước 4: không được khởi động lại thì dùng py-spy

Ở môi trường khách, pipeline thường đã chạy sẵn trong một worker và bạn không được dừng nó để bọc cProfile vào. Đó là lúc cần đến py-spy, một sampling profiler chạy bên ngoài tiến trình. Overhead của nó rất thấp, nên dùng được trên code production mà không phải sửa code hay khởi động lại.

Tài liệu Python cũng nói rõ cái giá phải trả: profiler lấy mẫu chỉ cho biết một cách tương đối thời gian đi đâu.

Trên laptop, hãy tập trước với script mẫu (bản chưa sửa):

py-spy record -o profile.svg -- python slow.py

Dấu -- tách phần lệnh mà py-spy sẽ khởi chạy. Mở profile.svg trong trình duyệt: khối rộng nhất là nơi thời gian đi qua nhiều nhất, và nó phải khớp với kết luận ở bước 1.

Nếu muốn xem tương tác và phóng to từng nhánh, hãy xuất sang định dạng speedscope:

py-spy record --format speedscope -o profile.json -- python slow.py

Với tiến trình đang chạy, py-spy còn hai lệnh nữa, đều gắn vào tiến trình theo PID. py-spy top cho xem trực tiếp hàm nào đang ngốn CPU. py-spy dump in call stack hiện tại của từng thread Python. Hãy xem py-spy dump --help để biết cờ chính xác trên bản bạn đã cài.

Phân biệt “chậm” với “treo” giúp bạn chọn đúng lệnh nhanh hơn. Tài liệu xử lý sự cố của Dagster khuyên dùng dump khi job bị treo, vì bản dump từng thread thường cho thấy ngay chỗ đang kẹt. Khi code chỉ chạy chậm, hãy dùng record để lấy flame graph.

Bước 5: container và cluster của khách

Đây là chỗ hầu như ai cũng vướng ở lần đầu. Trên Linux, cấu hình mặc định đòi quyền root để gắn vào một tiến trình không phải tiến trình con. Trong Docker, seccomp profile mặc định chặn đúng syscall mà py-spy dùng để đọc bộ nhớ của tiến trình khác, nên container phải được chạy với capability này:

docker run --cap-add SYS_PTRACE <image>

Kubernetes mặc định bỏ SYS_PTRACE, nên bạn phải thêm nó vào security context của pod. Dagster khuyên hỏi admin cluster trước xem thay đổi tạm thời này có chấp nhận được không. Ở chỗ khách, đó là việc bắt buộc, không phải phép lịch sự.

Lời khuyên thực tế: đưa yêu cầu này vào sớm, ngay tuần đầu tiên, như một mục trong checklist xin quyền truy cập. Khi sự cố xảy ra lúc hai giờ sáng, không ai muốn mở ticket bảo mật.

Kỹ năng này dùng thế nào ở chỗ khách?

Thử hình dung khách báo job enrich chậm dần qua từng quý. Bạn chạy py-spy top trên worker và thấy một hàm tra cứu chiếm phần lớn số mẫu.

Sau đó bạn tái hiện lỗi trên laptop bằng cProfile với dữ liệu mẫu và thấy cumulative time dồn vào đúng hàm đó. Thứ bạn mang về cho khách là flame graph trước và sau khi sửa, chứ không phải một giả thuyết.

Về sự nghiệp, đây là kinh nghiệm nên ghi vào CV kèm số đo: job nào, chậm bao nhiêu, dùng công cụ gì, nhanh lên bao nhiêu khi đo không bật profiler.

Khi JD có những cụm như “debug production issues” hay “performance tuning”, hãy chuẩn bị kể một câu chuyện như thế, kèm chi tiết về chuyện xin quyền SYS_PTRACE. Chi tiết đó cho người phỏng vấn thấy bạn đã thực sự làm việc trên hạ tầng của người khác.

Lần tới có người trong phòng họp nói “chắc tại database”, bạn đã có sẵn lệnh để trả lời bằng dữ liệu.