OpenTelemetry

Phần trước tự cài trace bằng tay để tránh phải bàn tới chi phí của bộ công cụ. Bài này bàn: opentelemetry-sdk thật, xuất OTLP qua HTTP tới một bộ thu thật, đo cả thời gian lẫn số byte. Con số về tốc độ thì như dự đoán. Con số về số span thực sự tới nơi thì không.

Bảng số liệu

Python 3.12 trong container, opentelemetry-sdk với OTLPSpanExporter trỏ tới một bộ thu tự viết đếm byte. Mỗi span có ba thuộc tính. 30 000 span mỗi lô, trung vị của ba lần chạy.

Giá mỗi span, khi mỗi request có 300 vòng tính toán thật (nền 16 285 ns):

Giá truyền, byte cho mỗi span thực sự được gửi:

Và số span thực sự tới nơi — đo bằng cách bọc lại exporter và đếm:

Điều đáng nhớ

Nói lại theo cách khác, vì hàng cuối là thứ tôi không đi tìm mà vấp phải:

BatchSpanProcessor mặc định vứt span, và chỉ ghi một dòng log. Với hàng đợi mặc định 2 048, một vòng lặp sinh span nhanh làm mất 62,5% — gần hai phần ba số trace không bao giờ rời khỏi tiến trình. Không có ngoại lệ, không có mã lỗi, không có chỉ số nào bật lên.

Và nghịch lý: dịch vụ càng nhanh thì càng mất nhiều trace. Với 1 000 vòng công việc mỗi span, không mất cái nào. Bỏ công việc đi cho span sinh thật nhanh thì mất 62,5%. Bộ xử lý theo lô chỉ theo kịp khi ứng dụng đủ chậm — nghĩa là chính những dịch vụ nhanh nhất, xử lý nhiều yêu cầu nhất, là nơi dữ liệu trace kém tin cậy nhất.

Tăng hàng đợi vừa giữ được span vừa nhanh hơn. Đặt max_queue_size = 30 000: không mất span nào, và mỗi span còn rẻ hơn 13% so với hàng đợi mặc định — vì không còn phải chạy nhánh xử lý "hàng đầy" và ghi log ở mỗi lần thêm.

SimpleSpanProcessor đắt gấp 21,4 lần, và còn tốn gấp 2,5 lần băng thông. Nó gửi từng span một, nên mỗi span phải mang trọn một khung protobuf riêng: 351,9 byte thay vì 134,9.

Lấy mẫu 10% rẻ hơn cả việc tạo span đầy đủ — 23 127 so với 26 368 ns. Span không được lấy mẫu thì không bao giờ được dựng ra, nên bạn tiết kiệm cả phần tạo lẫn phần xuất.

Vì sao

BatchSpanProcessor là một hàng đợi có kích thước cố định cộng một luồng nền định kỳ gom span thành lô rồi gửi đi. Khi luồng sinh span nhanh hơn luồng gửi, hàng đợi đầy. Lúc đó lựa chọn duy nhất còn lại là chặn luồng ứng dụng hoặc vứt span, và OpenTelemetry chọn vứt — đúng nguyên tắc "quan sát không được làm hỏng thứ đang bị quan sát".

Đó là một lựa chọn hợp lý, nhưng nó có hệ quả mà tài liệu không nhấn mạnh: dữ liệu trace của bạn im lặng trở nên không đầy đủ đúng lúc tải cao nhất. Và nó không hiện ra như một khoảng trống — nó hiện ra như một trace thiếu chặng, mà bạn sẽ đọc thành "chặng đó không được gọi".

Chuyện gửi theo lô rẻ hơn thì đơn giản: một yêu cầu OTLP mang thông tin về tài nguyên, phạm vi và khung protobuf một lần cho cả lô. Gửi 2 048 span trong một yêu cầu thì phần khung đó chia đều; gửi một span mỗi yêu cầu thì mỗi span phải trả trọn.

Còn lấy mẫu rẻ hơn tạo span vì TraceIdRatioBased quyết định trước khi span được dựng. Span không lấy mẫu trở thành một đối tượng rỗng không ghi thuộc tính, không vào hàng đợi, không được tuần tự hoá. Ba khoản tiết kiệm cộng lại lớn hơn khoản chi phí quyết định lấy mẫu.

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

• Kiểm tra max_queue_size ngay hôm nay. Mặc định 2 048 là quá nhỏ cho dịch vụ có lưu lượng cao. Đặt lên vài chục nghìn tốn thêm vài megabyte bộ nhớ và loại bỏ toàn bộ vấn đề.
• Theo dõi số span bị vứt như một chỉ số. Nếu bộ công cụ của bạn có sẵn thì bật lên; nếu không, hãy bọc exporter lại và tự đếm như tôi đã làm — mười dòng mã. Một hệ trace không đo được chính nó thì không đáng tin.
• Đừng dùng SimpleSpanProcessor ngoài môi trường phát triển. Gấp 21,4 lần thời gian và 2,5 lần băng thông, đổi lấy việc thấy span ngay lập tức. Chỉ đáng khi đang gỡ lỗi chính hệ trace.
• Lấy mẫu là công cụ tốt nhất trong bảng này. 10% lấy mẫu cho chi phí +42% thay vì +139%, và giảm băng thông mười lần. Với lấy mẫu theo đuôi thì bạn còn giữ được đúng những trace đáng quan tâm.
• Ngân sách băng thông: 134,9 byte mỗi span. Một dịch vụ 5 000 yêu cầu mỗi giây với bốn span mỗi yêu cầu là 2,6 MB/s, tức 217 GB mỗi ngày nếu không lấy mẫu. Con số đó thường mới là lý do thật khiến người ta bật lấy mẫu.

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

Đây là Python, và ngôn ngữ chi phối phần thời gian. Chi phí tạo span 8,4 µs khi không có công việc gì kèm theo là con số của một ngôn ngữ động; SDK cho Go hay Rust rẻ hơn nhiều bậc. Cái tôi tin là thứ tự và tỷ lệ giữa các cấu hình, cùng với toàn bộ phần đo số byte và số span bị vứt — hai thứ đó không phụ thuộc ngôn ngữ.

Bộ thu của tôi là một máy chủ HTTP mười dòng, không phải OpenTelemetry Collector thật. Nó nhận và đếm byte, thế thôi. Một Collector thật có xử lý, có hàng đợi riêng, có thể đẩy ngược áp lực về phía ứng dụng — và khi đó tỷ lệ vứt span sẽ khác. Con số 62,5% của tôi là trường hợp bộ thu nhanh nhất có thể; với bộ thu chậm hơn, nó tệ hơn.

Tôi đo trong một luồng duy nhất. Ứng dụng thật sinh span từ nhiều luồng cùng lúc, và hàng đợi của BatchSpanProcessor có khoá. Tranh chấp khoá sẽ làm chi phí mỗi span tăng lên, và tôi không đo phần đó.

Một phép đo phải vứt đi hoàn toàn, và cách nó lộ ra. Lượt đo đầu tiên cho nền 82 µs mỗi span cho một hàm chỉ chạy 300 phép nhân. Con số đó không hợp lý — 300 phép nhân số nguyên trong Python phải quanh 16 µs.

Nguyên nhân là hàm công việc giả của tôi viết c = c*1103515245 + 1 mà không chặn bit. Số nguyên Python không có giới hạn kích thước, nên sau 300 vòng c đã có 2 713 chữ số và mỗi phép nhân là một phép nhân số lớn. Kiểm chứng riêng: bản không chặn bit tốn 79 800 ns, bản chặn 32 bit tốn 16 233 ns — chênh 4,9 lần.

Hậu quả không phải là một con số sai lệch nhẹ. Nền 82 µs lấn át thứ tôi đang đo: chi phí OpenTelemetry chỉ khoảng 10–22 µs, nên nó chìm vào nhiễu của chính hàm công việc, và nền dao động 81,6–86,5 µs giữa ba lần chạy đủ để nuốt trọn tín hiệu. Sau khi chặn bit, nền còn 16 285 ns và ổn định, các cột chênh nhau rõ ràng.

Bài học tôi mang sang phần sau: hàm công việc giả cũng phải được đo trước khi tin nó. Tôi dựng nó để làm nền, rồi mặc định coi nền là thứ đã biết — trong khi nó là thứ tôi chưa bao giờ kiểm.

Thử ba mươi giây

docker run --rm python:3.12-slim sh -c '
pip -q install opentelemetry-sdk
python - <<EOF
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import BatchSpanProcessor, SpanExporter, SpanExportResult

class Dem(SpanExporter):
    def __init__(self): self.n = 0
    def export(self, spans):
        self.n += len(spans); return SpanExportResult.SUCCESS
    def shutdown(self): pass
    def force_flush(self, t=30000): return True

for qs in (2048, 50000):
    d = Dem(); p = TracerProvider()
    p.add_span_processor(BatchSpanProcessor(d, max_queue_size=qs))
    tr = p.get_tracer("x")
    N = 30000
    for i in range(N):
        with tr.start_as_current_span("s"): pass
    p.force_flush(); p.shutdown()
    print("max_queue_size=%-6d  tao %d  xuat %d  MAT %.1f%%"
          % (qs, N, d.n, 100*(N-d.n)/N))
EOF'

Dòng đầu là cấu hình mặc định của bạn. Con số ở cuối dòng đó là phần trăm trace mà bạn tưởng mình đang thu thập nhưng không hề có.