Hàm 'nóng nhất' trong profiler lại vô can: 8 luồng chỉ chạy như 1,27 lõi vì bận chờ khóa

Hình dung một quản đốc đi tìm nút thắt của xưởng bằng cách ghi lại xem máy nào đang chạy. Anh ta thấy cái máy dập ở giữa xưởng lúc nào cũng bận rộn, bèn kết luận "máy dập là nút thắt, mua cái nhanh hơn đi". Nhưng anh ta không thấy điều quan trọng nhất: bảy công nhân đang xếp hàng đứng chờ tới lượt dùng đúng cái máy dập chung đó. Người đứng chờ thì không "chạy máy" nào cả, nên không lọt vào sổ ghi của anh ta — và cái máy dập bận rộn kia hóa ra là nạn nhân của hàng đợi, không phải thủ phạm. Profiler phẳng cho code đa luồng chỉ sai chỗ y hệt cách đó.

Ở bài trước ta đo speedup và thấy 10 lõi hiếm khi cho 10 lần. Câu hỏi kế tiếp rất thực tế: khi một chương trình đa luồng chậm hơn kỳ vọng, làm sao tìm ra điểm nghẽn? Công cụ tự nhiên là profiler. Nhưng profiler — nhất là loại "phẳng" xếp hạng hàm theo thời gian CPU — có một cách chỉ sai chỗ rất tinh vi với code đồng thời, đủ để bạn tối ưu nhầm hàm hàng tuần liền mà chương trình không nhanh lên chút nào. Tôi dựng một chương trình có nút thắt đồng bộ rõ ràng, đo các tín hiệu mà một profiler thật cung cấp, và chỉ ra tín hiệu nào nói đúng sự thật — trong container gcc:13 (8 luồng, 10 lõi, ARM).

Profiler phẳng chỉ sai chỗ

Một profiler phẳng (flat/self-time) hoạt động bằng cách lấy mẫu con trỏ lệnh nhiều lần mỗi giây, rồi thống kê xem CPU đang ở hàm nào. Kết quả là một bảng xếp hạng "hàm nào ngốn nhiều thời gian CPU nhất". Với code một luồng, đây là vàng: hàm đầu bảng thường đúng là chỗ cần tối ưu.

Với code đa luồng, nó có hai lỗ hổng chết người. Thứ nhất: một luồng đang chờ khóa thì không chạy — nó bị nhân treo trong futex, không tiêu CPU, nên không bị lấy mẫu như code của bạn. Thời gian chờ khóa — thứ có thể chiếm phần lớn wall-clock — gần như vô hình trong hồ sơ phẳng, đúng như người xếp hàng không lọt vào sổ ghi của quản đốc. Thứ hai, hệ quả trực tiếp: hàm chạy bên trong vùng găng (critical section) là thứ duy nhất đang thực sự chạy khi những luồng khác nằm chờ, nên nó nổi lên "nóng" nhất — và bạn bị dụ đi tối ưu chính nó, trong khi vấn đề thật là sự chờ đợi mà nó gây ra cho bảy luồng kia.

Để đọc đúng điểm nghẽn đồng bộ, cần hai tín hiệu khác: (1) tỉ số CPU tổng trên wall-clock — bằng "số lõi hiệu quả" đang chạy; nếu nó thấp hơn số luồng nhiều, các luồng đang chờ chứ không thiếu CPU. Và (2) thời gian chờ khóa trên wall — cao nghĩa là nút thắt là đồng bộ, không phải bản thân hàm.

Đo: hai tín hiệu thật

Tôi cho 8 luồng làm cùng một tổng lượng việc, mỗi vòng gồm phần việc ngoài khóa (song song thật) và một phần nhỏ bên trong một khóa. Chạy hai cấu hình: [A] một khóa chung cho cả 8 luồng, và [B] mỗi luồng một khóa riêng (không tranh chấp). CPU tổng lấy từ getrusage (cộng thời gian mọi lõi), thời gian chờ khóa đo bằng clock_gettime bao quanh pthread_mutex_lock:

tín hiệu                    | [A] khóa chung | [B] khóa riêng
wall (cùng tổng việc)       | 0,652 s        | 0,081 s  (nhanh 8×)
CPU tổng (u+s, getrusage)   | 0,830 s        | 0,624 s
song song hiệu quả=CPU/wall | 1,27 lõi       | 7,71 lõi
chờ khóa / wall (mỗi luồng) | 81%            | 1%
self-time hàm work()        | 0,036 s (nóng) | 0,038 s (nóng)

Đọc cấu hình [A]: 8 luồng, 10 lõi, mà song song hiệu quả chỉ 1,27 lõi. Đây là cờ đỏ lớn nhất — bạn xin 8 luồng chạy song song, thực tế chỉ hơn một lõi làm việc tại mỗi thời điểm. Cùng lúc, mỗi luồng dành 81% wall-clock chỉ để chờ khóa. Nút thắt hiện ra rõ mồn một: các luồng xếp hàng trước một khóa chung, tuần tự hóa gần như hoàn toàn, đúng cái lock convoy ta đã đo.

Bây giờ [B] — cùng tổng việc, chỉ đổi khóa chung thành khóa riêng: wall giảm còn 0,081 s, nhanh 8 lần, song song hiệu quả vọt lên 7,71 lõi, chờ khóa chỉ còn 1%. Không một dòng nào của hàm tính toán thay đổi.

(Môi trường đo: container gcc:13 trên host ARM AArch64, 8 luồng/10 lõi, CPU tổng từ getrusage, chờ khóa đo quanh pthread_mutex_lock. Con số đổi theo máy; điều bền vững là: song song hiệu quả thấp + chờ khóa cao lộ nút thắt mà self-time giấu.)

Hai niềm tin đối nghịch, cùng sai

Tôi vào đo với hai niềm tin rất phổ biến. Thứ nhất: "hàm nóng nhất trong profiler là chỗ cần tối ưu". Thứ hai: "CPU bận thì nghĩa là thiếu CPU — cần thuật toán nhanh hơn hoặc thêm lõi". Phép đo đa luồng phá cả hai.

Nhìn dòng cuối bảng: trong cả hai cấu hình, hàm work() có self-time gần như y hệt (0,036 và 0,038 s) và trong cả hai nó là hàm nóng nhất hồ sơ phẳng — vì nó là nơi duy nhất CPU thực sự chạy code của tôi (cái máy dập luôn bận). Một profiler phẳng sẽ chỉ vào work() ở cả [A] lẫn [B] và nói "tối ưu tôi đi". Nhưng ở [A], work() hoàn toàn vô can: nó chỉ chạy 0,036 s mỗi luồng, trong khi mỗi luồng mất 0,526 s (81% của 0,652 s) chỉ để chờ. Mài giũa work() cho nhanh gấp đôi thì [A] gần như không nhúc nhích — vì thời gian không nằm trong work(), mà nằm trong sự chờ đợi cái khóa chung tạo ra. Thứ thật sự sửa được [A] là tách khóa ([B]) — nhanh 8 lần mà không đụng một chữ vào work(). Hàm nóng nhất là nạn nhân (code duy nhất còn chạy), không phải thủ phạm (hàng đợi).

Cái bẫy thứ hai cũng lộ, ngược hướng: ở [A], CPU tổng (0,830 s) chỉ nhỉnh hơn wall (0,652 s) một chút, và người nhìn "CPU đang bận" dễ kết luận "chương trình CPU-bound, cần tối ưu tính toán hoặc thêm lõi". Sai — tỉ số CPU/wall = 1,27 tiết lộ rằng phần lớn thời gian không có lõi nào làm việc; chúng đang ngủ chờ khóa. Thêm lõi hay thuật toán nhanh hơn đều vô ích khi nút thắt là sự chờ. Hai niềm tin gặp nhau ở một sự thật: với đa luồng, đừng đọc profiler bằng câu hỏi "hàm nào nóng"; đọc bằng "song song hiệu quả bao nhiêu, và thời gian chờ nằm ở đâu". Thủ phạm (chờ khóa) trốn khỏi hồ sơ phẳng vì nó không tiêu CPU — người xếp hàng không vào sổ.

Về đến code hằng ngày

Điều đầu tiên: đo song song hiệu quả (CPU tổng / wall) trước khi tin bất kỳ bảng xếp hạng hàm nào. Đây là một phép chia rẻ tiền — getrusage cho CPU tổng, đồng hồ treo tường cho wall — nhưng nó trả lời câu quan trọng nhất: chương trình có thật sự chạy song song không? Nếu bạn có N luồng mà tỉ số chỉ ra 1-2 lõi hiệu quả, thì dù profiler chỉ hàm nào, vấn đề thật là các luồng đang chờ nhau — hãy đi tìm khóa, tranh chấp, hoặc false sharing.

Điều thứ hai: khi nghi ngờ đồng bộ, đo trực tiếp thời gian chờ khóa. Bao clock_gettime quanh chỗ lấy khóa (hoặc dùng công cụ đo lock contention của nền tảng) và xem mỗi luồng dành bao nhiêu phần trăm wall để chờ. 81% như [A] là bản án rõ ràng cho một khóa quá to hoặc quá chung; cách chữa là thu nhỏ vùng găng hoặc tách khóa/sharding, không phải tối ưu code bên trong khóa.

Chỗ này chính là lý do các profiler đồng thời nghiêm túc đều có chế độ "nhìn thấy sự chờ đợi", vì on-CPU sampling bỏ sót nó. async-profiler của JVM có chế độ wall-clock (đếm cả luồng đang chờ) bên cạnh chế độ cpu, và thread dump của Java hiện luồng ở trạng thái BLOCKED/WAITING — chính là "off-CPU". Go có pprof với block profile và mutex profile (go tool pprof trên -blockprofile) đo đúng thời gian goroutine chờ khóa/kênh. Cả một trường phái gọi là off-CPU flame graph (Brendan Gregg) sinh ra để trực quan hóa thời gian không chạy. Và phương pháp USE (Utilization/Saturation/Errors) trong vận hành nhắc: "utilization" (CPU bận) không đủ, phải nhìn "saturation" (xếp hàng chờ). Mẫu số chung: công cụ tốt đo cả thời gian không chạy — đúng cái quản đốc phải đếm cả người đứng chờ, không chỉ máy đang chạy.

Muốn tự thấy thì lần tới khi một chương trình đa luồng chậm và bạn định mở profiler, hãy làm một phép tính rẻ tiền trước: lấy tổng thời gian CPU (trên Linux, time ./prog cho bạn user+sys) chia cho thời gian thực (real). Nếu chương trình dùng 8 luồng mà tỉ số đó chỉ ra ~1-2, thì dù bảng xếp hạng hàm chỉ vào đâu, sự thật là các luồng đang chờ nhau — và câu hỏi đúng không phải "hàm nào chậm" mà "chúng chờ ở đâu". Vài phút với phép chia CPU-trên-wall đó bắt được điều mà một giờ nhìn bảng self-time có thể bỏ lỡ hoàn toàn: với đồng thời, thời gian đắt nhất thường là thời gian không chạy, và đó chính là thứ một profiler phẳng không thấy.