BatchSpanProcessor mặc định lặng lẽ vứt 62,5% số trace của tôi — và nghịch lý là dịch vụ càng nhanh càng mất nhiều

Tưởng tượng một bưu điện nhỏ có đúng một hòm thư, và người đưa thư chỉ ghé gom mỗi vài phút. Khi thư đến lai rai, mọi lá đều được chuyển đi. Nhưng vào giờ cao điểm, thư đổ về nhanh hơn tốc độ gom, hòm đầy — và lá thư thứ hai nghìn lẻ một, thay vì được giữ lại, bị ném thẳng vào sọt rác, lặng lẽ, không ai báo cho người gửi. Điều trớ trêu: bưu điện càng đông khách thì càng nhiều thư biến mất. BatchSpanProcessor của OpenTelemetry chính là cái bưu điện đó, và bài này tôi đo xem nó ném đi bao nhiêu.

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. (Đo trong container Python 3.12, không có phần cứng đặc biệt nào.)

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:

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. Đây đúng là kiểu hỏng câm lặng mà cả sê-ri này cứ đâm vào mãi.

Và nghịch lý làm tôi ngồi lặng: 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. Đúng chỗ bạn cần trace nhất lại là chỗ nó thủng 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. Đừng đụng tới nó ngoài môi trường phát triển.

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 span bị vứt

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 rõ rà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". Một lời nói dối thầm lặng, đúng loại khó chịu nhất.

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 công việc hằng ngày

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

Cùng một cái bẫy "hàng đợi đầy thì vứt câm lặng", đổi ngăn xếp

Chuyện "một buffer/queue có giới hạn, đầy thì âm thầm bỏ dữ liệu thay vì chặn, và chỉ ghi một dòng log" không riêng gì OpenTelemetry — nó là mẫu backpressure lặp lại ở mọi hệ có producer nhanh hơn consumer.

Trong thế giới Java, đây đúng là câu chuyện của mọi async appender log: Logback AsyncAppender mặc định có queueSize=256 và bỏ các sự kiện mức thấp khi hàng đợi đầy tới 80% (discardingThreshold). Log4j2 async cũng vậy. Nhiều người tưởng chuyển sang async là "log nhanh hơn" mà không biết mình vừa đánh đổi bằng việc mất log dưới tải — đúng cái bẫy 62,5% ở trên, chỉ ở tầng logging. Và một ThreadPoolExecutor với hàng đợi có giới hạn cũng vậy: đầy thì RejectedExecutionHandler quyết định vứt hay chặn.

Trong Go, mẫu này hiện ra trần trụi qua channel có buffer: ch := make(chan T, 2048) với một select { case ch <- x: default: /* vứt */ } là idiom vứt-khi-đầy phổ biến, và chính OTel Go SDK cũng có max_queue_size y hệt. Cái đẹp của Go là backpressure nhìn thấy được trong code (channel đầy thì send chặn), nhưng cái dở là nhánh default vứt dữ liệu rất dễ viết mà quên đếm.

Còn ở cơ sở dữ liệu, họ hàng gần nhất là replication và WAL shipping: một replica chậm làm sender phải chọn giữa chặn (giữ WAL, phình đĩa primary — wal_keep_size) hay bỏ replica lại (nó rớt khỏi đồng bộ). Cùng đánh đổi "chặn producer hay bỏ dữ liệu", và cùng cần đo độ trễ hàng đợi (replication lag) như một chỉ số hạng nhất — đúng như "theo dõi số span bị vứt" ở trên.

Mẫu số chung: bất cứ khi nào có một hàng đợi giới hạn giữa producer nhanh và consumer chậm, hệ thống phải chọn giữa chặn producer hoặc vứt dữ liệu — và nếu nó chọn vứt (thường là mặc định), việc mất mát sẽ câm lặng và tệ nhất đúng lúc tải cao nhất. Phòng thủ luôn gồm hai phần: nới hàng đợi cho đủ đỉnh tải, và đo chính cái hàng đợi đó (số bị vứt, độ trễ) như một chỉ số, vì một hệ thống không đo được phần nó đánh rơi thì không thể tin nó đầy đủ. Nên câu hỏi đúng cho mỗi buffer async không phải "nó có nhanh không" mà là "khi nó đầy thì chuyện gì xảy ra, và tôi có đếm được điều đó không".

Muốn tự thấy con số của cấu hình mặc định, chạy thử:

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