Hình dung một dây chuyền bốn người chuyền tay nhau một gói hàng, người đầu đưa cho khách. Khách bấm giờ: hôm nay gói tới chậm gấp ba. Người đứng đầu dây — người duy nhất khách nhìn thấy — bị đổ lỗi ngay, dù anh ta chỉ cầm gói đúng một giây rồi chuyền đi. Kẻ thật sự ngồi ì với gói hàng nằm đâu đó giữa dây, khuất khỏi mắt khách. Trace phân tán sinh ra chính là để chỉ mặt cái người ngồi ì đó, và bài này đo cho thấy nó làm việc ấy ra sao.

Phần đầu sê-ri nói trace trả lời câu "chậm ở đâu trong request", nhưng lúc đó tôi đo trên một tiến trình duy nhất chia làm ba giai đoạn. Bài này làm thật: bốn dịch vụ HTTP riêng biệt gọi nối tiếp nhau, và câu hỏi là chuyện gì hiện ra ở dịch vụ đầu tiên khi một dịch vụ ở giữa chuỗi bắt đầu chậm. (Đo bằng bốn container Python thật trong mạng Docker, không có phần cứng đặc biệt nào.)

Bảng số liệu

Bốn container Python, mỗi cái một dịch vụ HTTP: svc-a → svc-b → svc-c → svc-d. Mỗi dịch vụ làm một khối lượng tính toán thật rồi gọi dịch vụ sau. Mỗi lần đo gửi 60 yêu cầu và lấy lần nằm ở trung vị; lặp lại cả bài ba lần.

Kịch bản A — mỗi chặng 10 ms:

Chặng Tổng Tự làm Chờ chặng sau
svc-a 45,06 ms 11,04 ms 34,02 ms
svc-b 33,26 ms 10,70 ms 22,55 ms
svc-c 21,85 ms 10,43 ms 11,42 ms
svc-d 10,80 ms 10,80 ms —

Độ trễ đo tại client: 45,77 ms. Tổng thời gian tự làm của cả bốn: 42,95 ms.

Kịch bản B — svc-c chậm 100 ms:

Chặng Tổng Tự làm
svc-a 136,84 ms 10,53 ms
svc-b 125,24 ms 11,05 ms
svc-c 113,60 ms 101,45 ms
svc-d 10,92 ms 10,92 ms

Độ trễ tại client: 137,45 ms.

Chi phí mỗi lần gọi HTTP nội bộ (kịch bản A):

Chặng Bên gọi thấy Bên nhận báo Chênh
client → svc-a 45,77 45,06 0,71 ms
svc-a → svc-b 34,02 33,26 0,76 ms
svc-b → svc-c 22,55 21,85 0,70 ms
svc-c → svc-d 11,42 10,80 0,62 ms

Trung bình 0,70 ms mỗi chặng.

Chỗ cột dễ nhìn nhất lại là cột sai

Điều đầu tiên đáng gằn giọng: từ ngoài nhìn vào, cả hai kịch bản chỉ là một con số. 45 ms và 137 ms. Chỉ số đặt ở svc-a — nơi duy nhất tiếp xúc với người dùng — nói được rằng hệ thống chậm hơn ba lần, và không nói thêm được gì. Bốn tín hiệu vàng ở svc-a đều đúng và đều vô dụng cho việc tìm nguyên nhân. Đây là giới hạn cứng của metric ở biên.

Trace thì chỉ thẳng vào thủ phạm: svc-c tự làm 101,45 ms trong khi svc-a, svc-b, svc-d đều quanh 10–11 ms. Không cần suy luận, không cần đoán — con số nằm ngay đó, chỉ mặt đặt tên.

Nhưng — và đây là cái bẫy tôi muốn bạn nhớ — cột "tự làm" mới là cột quan trọng, còn cột "tổng" thì lừa người. Nhìn cột "tổng", svc-a là 136,84 ms, lớn nhất bảng; nếu chỉ nhìn cột đó bạn sẽ hùng hổ đi điều tra nhầm dịch vụ. svc-a lớn vì nó bao trùm cả chuỗi, chứ không phải vì nó chậm. Nó chỉ đứng chờ.

Còn một con số làm tôi thấy nhẹ nhõm: chi phí gọi nhau nhỏ hơn nhiều so với nỗi lo thường gặp — 0,70 ms mỗi chặng. Nhưng nó nhân theo số chặng: bốn chặng là 2,8 ms, mười chặng là 7,0 ms, hai mươi chặng là 14,0 ms. Đó là khoản thuế cố định của việc chia nhỏ dịch vụ, và nó chẳng phụ thuộc gì vào việc mỗi dịch vụ làm gì bên trong.

Vì sao "span dài nhất" là câu hỏi sai

Một trace là một cây span, và mỗi span có hai con số khác nhau về bản chất: thời lượng của nó và thời gian nó tự làm việc. Span của svc-a kéo dài suốt cả yêu cầu vì nó đang chờ svc-b, cái đang chờ svc-c, cái đang chờ svc-d. Thời lượng của span cha luôn bao trùm mọi span con — đó là bản chất của cây, không phải dấu hiệu bệnh.

Vì thế "span nào dài nhất" gần như luôn là span gốc, và đó là một câu hỏi vô nghĩa. Câu hỏi đúng là "span nào có thời gian tự làm lớn nhất" — tức thời lượng của nó trừ đi tổng thời lượng các span con. Trong kịch bản B, con số đó là 101,45 ms cho svc-c và quanh 10 ms cho ba chặng kia.

Còn 0,70 ms mỗi chặng gồm những gì: mở kết nối TCP, dựng và phân tích yêu cầu HTTP, tuần tự hoá và giải tuần tự hoá JSON, cộng thời gian đi lại trên mạng ảo của Docker. Với dịch vụ thật qua mạng thật, con số này lớn hơn — nhưng cấu trúc của nó không đổi. Có một kiểm chứng tôi thích ở đây: tôi tính chi phí gọi nhau bằng hai cách hoàn toàn độc lập — cộng bốn khoản chênh giữa bên gọi và bên nhận được 2,79 ms; lấy độ trễ tại client trừ tổng thời gian tự làm được 2,82 ms. Hai cách lệch nhau 0,03 ms. Đó là loại kiểm chứng khiến tôi tin bảng số liệu; nếu chúng lệch nhau nhiều thì hẳn tôi đã bỏ sót cái gì đó.

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

  • Khi đọc trace, sắp xếp theo thời gian tự làm, không theo thời lượng. Mọi công cụ trace đều hiện cả hai; cột dễ nhìn nhất là cột sai. Nếu công cụ của bạn gọi nó là "self time" hay "exclusive duration" thì đó chính là cột cần nhìn.
  • Đặt trace trước khi cần nó. Trong kịch bản B, không có lượng metric nào ở svc-a giúp bạn tìm ra svc-c. Bạn sẽ phải đi hỏi từng đội một, và mỗi đội sẽ nhìn vào bảng điều khiển của mình rồi nói "chỗ tôi bình thường" — điều mà cả svc-a, svc-b và svc-d đều nói đúng.
  • Tính khoản thuế chuỗi khi thiết kế. Ở 0,70 ms mỗi chặng, một luồng xử lý đi qua mười dịch vụ tốn 7 ms chỉ để các dịch vụ nói chuyện với nhau. Nếu ngân sách độ trễ của bạn là 50 ms thì đó đã là 14% tiêu vào việc không làm gì cả.
  • Đừng tối ưu chặng có span dài nhất. Hãy tối ưu chặng có thời gian tự làm lớn nhất, và nếu mọi chặng đều nhỏ mà tổng vẫn lớn thì vấn đề là số chặng, không phải chặng nào cả.

Cùng một cái bẫy "tổng vs tự làm", đổi ngăn xếp

Chuyện "thời lượng bao trùm đánh lừa, còn thời gian tự làm mới chỉ đúng thủ phạm" không riêng gì trace phân tán — nó là nguyên tắc đọc mọi hồ sơ có cấu trúc cây.

Trong Java, đây đúng là bài học vỡ lòng khi đọc một profiler như async-profiler hay JFR: cây call-stack cho bạn total time và self time của mỗi phương thức, và người mới luôn nhìn nhầm total. main() bao trùm 100% thời gian chương trình nhưng tự nó chẳng làm gì; kẻ đáng tối ưu là phương thức lá có self time cao. Y hệt svc-a với svc-c, chỉ khác đây là cây lời gọi trong một JVM thay vì cây span qua bốn tiến trình.

Trong Go, pprof phân biệt tường minh flat (tự làm) và cum (tích luỹ, bao trùm) — đúng hai cột của bài này, chỉ đổi tên. Ai đọc go tool pprof mà sắp theo cum sẽ luôn thấy main.main hoặc runtime ở đỉnh và chẳng học được gì; sắp theo flat mới ra hàm thật sự đốt CPU.

Còn ở cơ sở dữ liệu, EXPLAIN ANALYZE của PostgreSQL cho một cây kế hoạch mà mỗi nút có actual time gồm cả thời gian của các nút con. Một nút cha (như một Hash Join ở đỉnh) luôn có thời gian lớn nhất vì nó bao trùm; thủ phạm thật thường là một nút lá — một Seq Scan quét cả bảng — mà bạn chỉ thấy khi trừ đi phần con. Cùng một phép trừ, cùng một cái bẫy.

Mẫu số chung: trong bất kỳ cấu trúc cây thời gian nào, nút cha luôn trông "đắt nhất" chỉ vì nó chứa các con, nên số đo có ý nghĩa duy nhất là phần một nút tự tiêu, sau khi đã trừ đi các con của nó. Cột tổng/cumulative/total sinh ra để cho bạn thấy hình dạng, không phải để chỉ thủ phạm. Nên khi đứng trước bất kỳ hồ sơ dạng cây nào — trace, call-stack, query plan — câu hỏi đầu tiên luôn là "cái này tự làm bao nhiêu", chứ không phải "cái này dài bao nhiêu".

Muốn tự thấy hai cột dẫn tới hai kết luận khác nhau ra sao, chạy thử:

# Doc mot trace bat ky: cot dung nhin la "tu lam", khong phai "tong"
python3 - <<'EOF'
# so lieu that do duoc o kich ban B
spans = [("svc-a", 136.84, 10.53), ("svc-b", 125.24, 11.05),
         ("svc-c", 113.60, 101.45), ("svc-d", 10.92, 10.92)]

print("Sap theo TONG  (cot de nhin nhat, va la cot sai):")
for t, tong, tu in sorted(spans, key=lambda s: -s[1]):
    print("   %-8s %8.2f ms" % (t, tong))
print("\nSap theo TU LAM (cot dung):")
for t, tong, tu in sorted(spans, key=lambda s: -s[2]):
    print("   %-8s %8.2f ms" % (t, tu))
EOF

Danh sách thứ nhất bảo bạn đi tìm svc-a. Danh sách thứ hai bảo bạn đi tìm svc-c. Chỉ một trong hai dẫn tới chỗ thật sự có vấn đề.