Bạn đang ngồi ở một bàn cà phê, để cuốn sách lại rồi đứng dậy đi gọi nước. Lúc quay ra, bạn ngồi vào một cái bàn trông y hệt — cùng kiểu, cùng chỗ — nhưng không phải cái bàn lúc nãy, và cuốn sách không còn đó. runOnContext gọi từ một luồng lạ làm đúng chuyện đó: nó đưa bạn về một context của Vert.x, không phải cái context bạn rời đi, và trace id để lại trong context cũ biến mất. Bài này lần theo context local của Vert.x qua bảy kiểu chặng, tìm đúng bốn chỗ nó rơi, và chỗ khó thấy nhất chính là cái bàn nhầm đó.

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:

Thông lượng
/tran (không làm gì) 104 808 req/s
putLocal + getLocal mỗi request 108 394 req/s
Event bus có bộ chặn ra 102 178 req/s
Event bus tắt bộ chặn 101 126 req/s
Có cả hai bộ chặn (event bus + HTTP) 109 052 req/s

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

Chặng Context local Cần làm gì
compose, map, onSuccess còn —
setTimer, setPeriodic còn —
Callback WebClient còn —
executeBlocking còn ThreadLocal thì mất
Request HTTP đi ra mất bộ chặn của WebClient
Thông điệp event bus mất addOutboundInterceptor
vertx.runOnContext từ luồng lạ mất giữ Context rồi goc.runOnContext
Future.fromCompletionStage mất truyền Context vào overload

Muốn tìm chỗ đứt trong ứng dụng của mình mà không cần dựng gì, rắc một dòng in ra id vào đầu mỗi callback trên đường mã bạn quan tâm rồi gửi đúng một request:

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

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

Mẫu số chung

Cái bẫy tinh vi nhất của bài không phải "context mất khi ra khỏi tiến trình" — mà là bạn quay về một context giống hệt, tưởng là cái context cũ. runOnContext từ luồng lạ cho bạn một cái bàn trông y đúc, không phải cái bàn có cuốn sách của bạn. Đây là lằn ranh danh tính so với tương đương mà rất nhiều bug ẩn nấp: một new Thread() không thừa hưởng ngữ cảnh của luồng cha, một transaction mới trông giống hệt nhưng không phải transaction đang mở (đúng cái bẫy cn với pg ở phần 35), một instance mới từ một DI scope tưởng là instance cũ. Cách chữa luôn giống nhau và ngược với trực giác: giữ lấy tham chiếu tới cái cụ thể TRƯỚC khi rời đi, đừng cố lấy lại nó SAU — vì lấy-lại cho bạn "một cái", còn giữ-tham-chiếu mới cho bạn "cái đó". Và nó hỏng lặng lẽ theo kiểu tệ nhất: null được vá bằng một id mới, nên vết không mất mà tách làm hai — một request hoá hai, dữ liệu sai mà trông hoàn toàn hợp lệ.

Điều thứ hai, về nơi đặt một mối-lo-cắt-ngang: trace, auth, metric — những thứ phải có ở mọi lối đi — thuộc về một chốt chặn duy nhất, không phải rắc tay ở từng lời gọi. Một addInterceptor toàn cục đúng ở mọi request kể cả cái bạn chưa viết; đính header bằng tay thì đúng ở mọi chỗ bạn nhớ, và đứt ở đúng cái chỗ duy nhất ai đó quên — gần như luôn là đường mã hiếm chạy, tức đúng đường lúc sự cố bạn cần trace nhất. Cùng nguyên tắc ấy đặt kiểm quyền vào middleware chứ không vào từng handler, đặt ghi log vào một filter, đặt retry vào một lớp bọc client: một mối lo xuyên suốt mà cài rải rác thì độ phủ của nó chỉ bằng trí nhớ của người cài — hãy đặt nó ở ranh giới mà mọi luồng bắt buộc đi qua.

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