Bảng độ trễ đứng yên 13,9 ms trong khi khách chờ 600 ms — chỉ số mặc định nói dối rất thuyết phục

Hãy nghĩ tới một nhà hàng đo thời gian phục vụ bằng cách bấm giờ từ lúc bếp bắt đầu nấu. Món ra nhanh, đồng hồ báo "trung bình 8 phút", mọi biểu đồ đều xanh. Nhưng thực khách thì ngồi chờ bàn cả tiếng ngoài cửa — và cái tiếng đồng hồ đó không hề đếm, vì nó chỉ bắt đầu tính khi người ta đã được ngồi xuống. Bộ chỉ số độ trễ mặc định của Vert.x đo đúng theo kiểu ấy, và đó là điều tôi muốn kể ở bài này.

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:

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. Đúng cái đồng hồ nhà hàng chỉ bấm từ lúc bắt đầu nấ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:

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. Điều lặp lại: 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, còn 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.

Nếu bạn đã có Prometheus, có một câu truy vấn cho biết ngay ứng dụng có dính điểm mù kể trên không. Đối chiếu độ trễ khách cảm nhận (đo ở tầng nginx / load balancer) với độ trễ ứng dụng tự báo:

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

Mẫu số chung

Một phép đo độ trễ bắt đầu bấm giờ ở sai chỗ thì không chỉ sai một chút — nó có hệ thống giấu đi đúng phần tệ nhất. Đồng hồ khởi động lúc dịch vụ bắt đầu làm việc, nên toàn bộ khoảng khách nằm xếp hàng ngoài cửa rơi khỏi số liệu; và nghịch lý là hệ càng quá tải, cái bị giấu càng lớn, đúng lúc bạn cần con số thật nhất. Đây là "coordinated omission", và một khi nhận ra hình dạng của nó thì thấy nó ở khắp nơi: một công cụ đo tải tự nó khựng lại khi máy chủ khựng, nên báo cáo đẹp ngay giữa cơn sập; thời gian truy vấn CSDL tự báo bỏ quên khoảng chờ trong pool kết nối; response_time server-side bỏ quên thời gian request nằm ở kernel socket buffer. Chữa thì cùng một hướng: đo ở ranh giới gần người dùng nhất mà bạn với tới được — client, nginx, load balancer — chứ đừng tin cái đồng hồ đặt sau hàng đợi.

Điều thứ hai, âm thầm hơn: một bộ chỉ số mặc định trả lời những câu hỏi tác giả của nó nghĩ tới, không nhất thiết là câu hỏi quan trọng nhất với bạn. Câu hỏi sống-còn của một ứng dụng Vert.x — event loop có bị chặn không — lại không có chỉ số sẵn nào; bảy dòng tự chế mới nói được điều mà 138 dòng có sẵn im lặng. Cùng khoảng trống ấy ở mọi hệ: bộ đếm mặc định của JVM đo GC pause nhưng không đo "luồng nào đang giữ khoá", một exporter Postgres cho hàng chục chỉ số mà thiếu đúng cái "truy vấn nào đang chờ lock". Nên đừng đọc dashboard như một danh sách sự thật; đọc nó như một danh sách những câu ai đó đã nghĩ tới hỏi — rồi tự hỏi câu quan trọng nhất của mình có nằm trong đó không, và nếu không, hãy tự cắm cây kim đo vào.

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