Trace bốn chặng

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.

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:

Độ 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:

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

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

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

Điều đáng nhớ

Nói lại theo cách khác:

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 được gì thêm. 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.

Trace 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 đó.

Và cột "tự làm" mới là cột quan trọng. Nhìn cột "tổng" thì svc-a là 136,84 ms — lớn nhất bảng, và nếu chỉ nhìn cột đó bạn sẽ đi điều tra nhầm dịch vụ. svc-a lớn vì nó bao trùm cả chuỗi, không phải vì nó chậ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ó không phụ thuộc vào việc mỗi dịch vụ làm gì.

Vì sao

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.

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 đáng nói ở đâ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, và nếu chúng lệch nhau nhiều thì tôi đã phải đi tìm xem mình bỏ sót cái gì.

Nghĩa là gì trong thực tế

• 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ả.

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

Chuỗi của tôi là tuần tự thuần tuý. Mỗi dịch vụ gọi đúng một dịch vụ sau rồi chờ. Hệ thống thật có nhánh song song, có lời gọi lặp trong vòng lặp, có cả những chặng chạy nền sau khi đã trả lời. Với những hình dạng đó, "thời gian tự làm" vẫn là con số đúng để nhìn, nhưng cách cộng chúng lại thì phức tạp hơn nhiều so với phép trừ đơn giản trong bài.

Con số 0,70 ms là của mạng ảo Docker trên cùng một máy. Không có chuyển mạch, không có mã hoá TLS, không có cân bằng tải, không có DNS. Mỗi thứ đó cộng thêm, và với dịch vụ qua nhiều vùng khả dụng thì riêng thời gian đi lại đã lấn át toàn bộ con số này. Tôi tin cấu trúc của phép đo, không tin con số tuyệt đối.

Tôi tự cài trace chứ không dùng thư viện. Mỗi dịch vụ tự đo thời gian của mình và gói kết quả vào chính phản hồi, nên tôi không cần đồng bộ đồng hồ giữa các container — một nguồn sai số mà hệ trace thật phải đối mặt. Đổi lại, phép đo của tôi không tính chi phí của bản thân việc trace: không có bộ thu, không có hàng đợi, không có lần gửi span nào qua mạng. Phần đó chính là bài tiếp theo của sê-ri.

Tôi không dựng trường hợp khó nhất, là khi độ chậm nằm ở chính khoảng giữa hai chặng — tức bên gọi thấy lâu mà bên nhận báo nhanh. Đó là dấu hiệu của xếp hàng ở tầng mạng hoặc ở bộ chấp nhận kết nối, và nó là loại sự cố mà bảng của tôi có thể phát hiện (cột "chênh" sẽ phình ra) nhưng tôi chưa dựng ra để đo.

Thử ba mươi giây

# 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ỗ có vấn đề.