Bật metrics cho Vert.x mất đúng một khối cấu hình. Cái khó không phải bật nó, mà là biết chỉ số nào đáng nhìn — và biết chỉ số nào sẽ không cho bạn biết điều bạn cần biết nhất.

VertxOptions vo = new VertxOptions().setMetricsOptions(
    new MicrometerMetricsOptions()
        .setPrometheusOptions(new VertxPrometheusOptions().setEnabled(true)
            .setStartEmbeddedServer(true)
            .setEmbeddedServerOptions(new HttpServerOptions().setPort(9090))
            .setEmbeddedServerEndpoint("/metrics"))
        .setLabels(EnumSet.of(Label.HTTP_METHOD, Label.HTTP_CODE, Label.HTTP_PATH,
                              Label.EB_ADDRESS, Label.POOL_NAME))
        .setJvmMetricsEnabled(true)
        .setEnabled(true));

Có sẵn những gì

Sau khi chạy một ít lưu lượng, /metrics cho 138 dòng thuộc 46 họ chỉ số — 23 của Vert.x, 23 của JVM. Nhóm của Vert.x chia làm bốn mảng:

Mảng Chỉ số
HTTP server requests, active_requests, response_time_seconds, request_bytes, response_bytes, active_connections, bytes_written
HTTP client requests, responses, active_requests, active_connections, queue_pending, queue_time_seconds, response_time_seconds, request_bytes, response_bytes, bytes_read
Event bus sent, received, delivered, processed, pending, handlers
Pool in_use, ratio, completed_total, queue_pending, queue_time_seconds, usage_seconds

Nhóm pool chỉ xuất hiện sau khi có ai đó gọi executeBlocking — trước đó nó không tồn tại, nên đừng hoảng nếu không thấy.

Điểm mù

Câu hỏi quan trọng nhất với một ứng dụng Vert.x là event loop có đang bị chặn không. Tôi tìm chỉ số đó trong 138 dòng:

grep -i 'blocked|eventloop|event_loop'  ->  1 dong
jvm_threads_states_threads{state="blocked",} 0.0

Một dòng duy nhất, và nó là chỉ số của JVM về luồng đang chờ khoá synchronized — không liên quan gì tới việc event loop có bị chiếm hay không. Vert.x không xuất chỉ số nào cho chuyện đó.

Vậy chỉ số nào phát hiện được? Tôi chặn event loop 300 ms mỗi request, chạy tải lên một đường hoàn toàn khác, rồi so cái client đo được với cái máy chủ báo cáo:

client do duoc      : 148 req/s | p50 305,0 ms | p95 599,9 ms
vertx_http_server_response_time_seconds_max{path="/nhanh"} :
    truoc  0,013901667
    trong  0,013901667      <-- khong nhuc nhich

Biểu đồ độ trễ của bạn đứng yên ở 13,9 ms trong khi người dùng chờ 600 ms. Không sai số, không lệch — nó không thay đổi lấy một chữ số.

Lý do nằm ở chỗ chỉ số này bắt đầu bấm giờ khi Vert.x bắt đầu xử lý request, chứ không phải khi request tới nơi. Event loop bị chiếm thì request nằm xếp hàng ở tầng socket, chưa được coi là đã bắt đầu; khi tới lượt, nó được xử lý trong một mili giây và ghi nhận là một mili giây. Toàn bộ thời gian chờ biến mất khỏi số liệu.

Đây là dạng "coordinated omission" — cùng một bệnh làm hỏng rất nhiều phép đo hiệu năng — nhưng ở đây nó nằm sẵn trong bộ chỉ số mặc định mà ai cũng dùng.

vertx_http_server_active_requests thì có phản ứng:

vertx_http_server_active_requests{path="/chan",}  0.0  ->  4.0

Nó là số request đang được xử lý dở, tức là độ sâu hàng đợi. Đó là chỉ số duy nhất trong bộ mặc định cho biết có thứ gì đó đang bị nghẽn.

Cảnh báo có sẵn của Vert.x cũng im lặng

Vert.x có bộ giám sát luồng bị chặn, nhưng ngưỡng mặc định — đọc thẳng từ VertxOptions — là:

maxEventLoopExecuteTime    = 2000 ms
maxWorkerExecuteTime       = 60000 ms
warningExceptionTime       = 5000 ms

Với block 300 ms như trong phép đo trên, log ghi được 0 dòng cảnh báo. Hai giây là ngưỡng rất rộng: một event loop bị chiếm 1,9 giây, lặp đi lặp lại, sẽ không sinh ra một dòng log nào trong khi mọi request qua nó đều chậm gấp hàng nghìn lần.

Nếu ứng dụng của bạn là loại độ trễ thấp, hạ ngưỡng đó xuống là việc nên làm ngay:

new VertxOptions().setMaxEventLoopExecuteTime(200).setMaxEventLoopExecuteTimeUnit(MILLISECONDS)

Tự làm chỉ số còn thiếu

Vì không có chỉ số nào cho độ trễ của event loop, cách rẻ nhất là để chính event loop tự đo mình: đặt một bộ định giờ định kỳ và xem nó trễ bao nhiêu so với lịch.

MeterRegistry so = BackendRegistries.getDefaultNow();
AtomicLong treNs = new AtomicLong();
so.gauge("do_tre_event_loop_ms", treNs, v -> v.get() / 1e6);

long[] mocTruoc = { System.nanoTime() };
vertx.setPeriodic(100, t -> {
    long nay = System.nanoTime();
    treNs.set(Math.max(0, (nay - mocTruoc[0]) - 100_000_000L));   // le ra phai dung 100 ms
    mocTruoc[0] = nay;
});

Đo thử:

luc ranh roi                 : do_tre_event_loop_ms 0.0
trong khi event loop bi chan : do_tre_event_loop_ms 205.627917

Từ 0 lên 205,6 ms. Bảy dòng mã cho ra chỉ số nói đúng điều mà 138 dòng kia không nói.

Lưu ý khi triển khai: chỉ số này đo một event loop — cái đang chạy Verticle đăng ký bộ định giờ. Muốn phủ hết thì đăng ký trong mỗi bản sao Verticle và gắn nhãn theo số hiệu, nếu không bạn chỉ nhìn thấy một phần tư sự thật trên một máy bốn nhân.

Sáu chỉ số đáng đặt cảnh báo

Sau tất cả những gì sê-ri này đã đo, đây là sáu thứ tôi sẽ gắn cảnh báo:

Chỉ số Vì sao Đã đo ở đâu
do_tre_event_loop_ms (tự chế) Không có gì trong bộ mặc định nói được chuyện này Bài này
vertx_http_server_active_requests Độ sâu hàng đợi — dấu hiệu sớm duy nhất có sẵn Bài này
vertx_http_client_queue_pending Pool client cạn: một hạ nguồn chậm kéo sập đường khác Phần 31
vertx_pool_queue_pending và vertx_pool_ratio Pool luồng chặn bão hoà Phần 31
vertx_eventbus_pending Thông điệp dồn nhanh hơn khả năng xử lý Phần 36
jvm_gc_pause_seconds_max Một lần GC dài chặn event loop y như mã chặn Phần 42 — cụm đá node vì GC dài

Và đừng đặt cảnh báo trên vertx_http_server_response_time_seconds như chỉ số duy nhất về sức khoẻ. Phép đo ở trên cho thấy nó có thể đẹp hoàn hảo trong lúc dịch vụ gần như đứng.

Một cái bẫy phiên bản nữa

vertx-micrometer-metrics 4.5.11 tìm lớp io.micrometer.prometheus.PrometheusMeterRegistry. Micrometer 1.13 đã đổi gói đó thành io.micrometer.prometheusmetrics, nên nếu Maven chọn 1.13 trở lên thì ứng dụng chết ngay lúc khởi động:

NoClassDefFoundError: io/micrometer/prometheus/PrometheusMeterRegistry
    at io.vertx.micrometer.backends.BackendRegistries.setupBackend

Ghim micrometer-registry-prometheus về nhánh 1.12 là chạy. Đây là cái bẫy thứ ba cùng kiểu trong sê-ri này — sau driver MongoDB và thư viện SCRAM của PostgreSQL. Bài học chung: Vert.x 4.5.x ghim chặt vào các nhánh thư viện của thời điểm nó ra mắt, và Maven thì luôn muốn kéo bản mới nhất. Khi một thư viện của bên thứ ba nổ ra NoClassDefFoundError ngay lúc khởi động, chỗ nhìn đầu tiên là phiên bản, không phải cấu hình.

Thử ba mươi giây

Nếu bạn đã có Prometheus, câu truy vấn này cho biết ngay ứng dụng có điểm mù kể trên không:

# do tre client cam nhan (neu ban co do o tang nginx / load balancer)
histogram_quantile(0.95, rate(nginx_request_duration_seconds_bucket[1m]))
  /
# do tre ma ung dung tu bao cao
histogram_quantile(0.95, rate(vertx_http_server_response_time_seconds_bucket[1m]))

Tỉ lệ này quanh 1 là hai bên đồng ý với nhau. Tỉ lệ 40 — như phép đo 599,9 ms so với 13,9 ms ở trên — nghĩa là toàn bộ thời gian chờ đang nằm ngoài tầm nhìn của ứng dụng, và bảng theo dõi của bạn đang nói dối một cách rất thuyết phục.

Phần sau bàn về kiểm thử ứng dụng Vert.x, và vì sao test bất đồng bộ hay xanh giả.