Trace id sống qua compose, timer và WebClient — rồi chết ở đúng bốn chỗ

Trong một ứng dụng đồng bộ, ThreadLocal là chỗ để trace id: một request một luồng, MDC của logger tự đính id vào mọi dòng log. Trong Vert.x, một request đi qua hàng chục callback trên nhiều luồng khác nhau, và ThreadLocal gần như vô dụng.

Vert.x có thứ thay thế: context local. Câu hỏi là nó sống sót qua những chặng nào. Tôi viết một request đi xuyên bảy kiểu chặng khác nhau rồi in ra id nhìn thấy được ở từng chỗ.

Gắn id ở cửa vào

static final String KHOA = "vet-id";

r.route().handler(c -> {
    String id = c.request().getHeader("x-vet-id");
    if (id == null) id = "vet-" + System.nanoTime();
    Vertx.currentContext().putLocal(KHOA, id);
    c.next();
});

static String xem(){
    Context c = Vertx.currentContext();
    return c == null ? "KHONG-CO-CONTEXT" : String.valueOf((Object) c.getLocal(KHOA));
}

Rồi cho request đi qua compose, setTimer, WebClient, executeBlocking, event bus, một luồng ngoài Vert.x, và CompletableFuture.

Kết quả

OK  0-ngay-tai-handler            = VET-123
OK  1-sau-compose                 = VET-123
OK  2-trong-setTimer              = VET-123
OK  3-callback-webclient          = VET-123
    3b-ha-nguon-nhan-header       = null            <-- mat
OK  4-trong-executeBlocking       = VET-123
    4b-thread-local-trong-worker  = MAT
    5-context-local-ben-kia       = null            <-- mat
    5b-thread-local-ben-kia       = MAT
    6-trong-luong-ngoai           = KHONG-CO-CONTEXT
    6c-sau-runOnContext           = null            <-- mat
    7-trong-CompletableFuture     = KHONG-CO-CONTEXT
    7b-sau-fromCompletionStage    = null            <-- mat

Tin tốt trước: context local sống sót qua mọi chặng bất đồng bộ nội bộ của Vert.x — chuỗi compose, bộ định giờ, callback của WebClient, và cả executeBlocking dù đoạn mã đó chạy trên luồng worker chứ không phải event loop. ThreadLocal thì chết ngay ở chặng worker, đúng như dự đoán.

Bây giờ tới bốn chỗ mất.

Chỗ mất 1 và 2: ra khỏi tiến trình

3b và 5 là cùng một câu chuyện: context local là thứ trong bộ nhớ của một context, nó không tự chui vào một request HTTP hay một thông điệp event bus. Sang tới bên kia là hết.

Với event bus thì bên kia là một Verticle khác, tức là một context khác, nên getLocal trả null. Vá bằng một bộ chặn toàn cục, viết một lần cho cả ứng dụng:

vertx.eventBus().addOutboundInterceptor(ctx -> {
    Context c = Vertx.currentContext();
    Object id = c == null ? null : c.getLocal(KHOA);
    if (id != null && ctx.message().headers().get("x-vet-id") == null)
        ctx.message().headers().add("x-vet-id", String.valueOf(id));
    ctx.next();
});

Với HTTP thì tương tự, chỉ khác chỗ móc vào:

((WebClientInternal) wc).addInterceptor(ctx -> {
    Context c = Vertx.currentContext();
    Object id = c == null ? null : c.getLocal(KHOA);
    if (id != null) ctx.request().headers().set("x-vet-id", String.valueOf(id));
    ctx.next();
});

Sau khi vá, cả hai đầu bên kia đều nhận được VET-123.

Một lưu ý thẳng thắn: trên Vert.x 4.5.11, addInterceptor của WebClient đòi ép kiểu sang WebClientInternal — một lớp trong gói impl, tức là API nội bộ có thể đổi giữa các phiên bản. Nó chạy, nhưng bạn đang dựa vào thứ không có cam kết tương thích. Nếu chuyện đó làm bạn khó chịu thì cách thay thế là bọc WebClient bằng một lớp mỏng của riêng bạn và chỉ gọi qua lớp đó — dài dòng hơn nhưng không phụ thuộc vào impl.

Điểm quan trọng chung cho cả hai: hãy viết bộ chặn toàn cục, đừng đính header bằng tay ở từng lời gọi. Đính tay thì đúng ở mọi chỗ bạn nhớ, và trace của bạn sẽ đứt ở đúng cái chỗ duy nhất ai đó quên — thường là đường mã hiếm khi chạy, tức đúng đường bạn cần trace nhất.

Chỗ mất 3 và 4: đi ra một luồng lạ rồi quay về

Hai chỗ này mới là chỗ tôi không lường trước.

bepRieng.submit(() -> {                       // luong cua rieng toi, khong phai cua Vert.x
    c.vertx().runOnContext(v -> {
        kq.put("6c-sau-runOnContext", xem());  // -> null
    });
});

Đoạn mã này trông như đã quay về đúng chỗ: nó gọi runOnContext, callback chạy trên một event loop của Vert.x, mọi thứ có vẻ ổn. Nhưng id đã mất.

Lý do: vertx.runOnContext gọi từ một luồng không phải của Vert.x thì không có cách nào biết bạn muốn quay về context nào, nên nó lấy — hoặc tạo mới — một context khác. Bạn quay về một context, không phải cái context. Cách vá là giữ lại tham chiếu trước khi rời đi:

final Context goc = Vertx.currentContext();          // giu lai TRUOC khi roi di
bepRieng.submit(() -> goc.runOnContext(v -> {        // quay ve DUNG context cu
    kq.put("6c-runOnContext-tren-context-goc", xem());   // -> VET-123
}));

CompletableFuture hỏng theo đúng kiểu đó, và vá theo đúng kiểu đó — dùng overload có nhận Context:

Future.fromCompletionStage(CompletableFuture.supplyAsync(..., bepRieng), goc)   // -> VET-123

Cả hai bản vá đều cho lại VET-123, và chính việc bản vá có tác dụng là bằng chứng cho chẩn đoán ở trên.

Điều làm hai chỗ này nguy hiểm là chúng hỏng lặng lẽ và cục bộ. Không ngoại lệ, không log, chỉ có getLocal trả null — mà null thì thường được xử lý bằng cách sinh một id mới, nên vết của bạn không biến mất, nó tách làm hai. Trên bảng theo dõi, một request bị đứt đôi trông giống hệt hai request riêng biệt, và bạn sẽ mất rất lâu để hiểu vì sao chặng cuối không bao giờ nối được với chặng đầu.

Chi phí

Đây là phần dễ chịu:

Không có khác biệt nào vượt mức nhiễu giữa các lần chạy. Mang trace id đi khắp nơi không tốn gì đo được ở quy mô 100 000 req/s — cùng kết luận với bộ giới hạn tần suất ở phần 29: thao tác nano giây biến mất hoàn toàn bên cạnh chi phí 9 500 ns của một request HTTP.

Nên đừng bỏ trace id vì sợ chậm. Lý do thật khiến người ta không có trace id là nó đứt ở bốn chỗ kể trên rồi bị bỏ dở, chứ không phải vì hiệu năng.

Còn ghi log thì sao

Context local giải quyết việc mang id đi, nhưng logger của bạn vẫn đọc MDC, mà MDC là ThreadLocal — và bảng đo ở trên cho thấy ThreadLocal chết ngay ở chặng worker đầu tiên.

Hai cách, cả hai đều phải làm thủ công:

• Đặt và xoá MDC ở mỗi ranh giới callback. Đúng nhưng dễ quên, và quên xoá thì id của request này dính sang request sau trên cùng luồng — sai lệch còn tệ hơn là không có gì.
• Đừng dùng MDC. Đọc id từ context local ngay tại chỗ ghi log, qua một hàm bọc mỏng. Dài dòng hơn nhưng không có trạng thái ẩn để rò rỉ.

Tôi nghiêng về cách thứ hai trong mã Vert.x, vì cách thứ nhất đòi bạn đúng ở mọi ranh giới callback, mà một ứng dụng bất đồng bộ có rất nhiều ranh giới như vậy.

Danh sách chỗ cần kiểm

Thử ba mươi giây

Tìm chỗ đứt trong ứng dụng của bạn mà không cần dựng gì:

static String xem(){
    Context c = Vertx.currentContext();
    return c == null ? "KHONG-CO-CONTEXT" : String.valueOf((Object) c.getLocal("vet-id"));
}

Rắc System.out.println("[" + xem() + "] ten-chang") vào đầu mỗi callback trên một đường mã bạn quan tâm, rồi gửi đúng một request. Dòng đầu tiên in ra null hay KHONG-CO-CONTEXT chính là ranh giới làm đứt vết — và bảng ngay phía trên cho biết phải vá kiểu gì.

Phần sau bàn về ghi log có cấu trúc và những gì đáng ghi trong một ứng dụng bất đồng bộ.