Log INFO bị vứt im lặng 99,4%, còn log ERROR kéo dịch vụ từ 108 315 xuống 720 req/s

Ghi log là thứ ai cũng làm và gần như không ai đo. Trong một ứng dụng bất đồng bộ, nó hỏng theo hai cách mà mã đồng bộ không có: stack trace mất hết ngữ cảnh, và bộ ghi log có thể chặn chính event loop.

Stack trace: 4 khung so với 20

Cùng một ngoại lệ ném ra từ hamC(), được gọi bởi hamB(), được gọi bởi hamA(). Đồng bộ:

do sau: 4 khung
  lab.LogBatDongBo.hamC(LogBatDongBo.java:48)
  lab.LogBatDongBo.hamB(LogBatDongBo.java:47)
  lab.LogBatDongBo.hamA(LogBatDongBo.java:46)
  lab.LogBatDongBo.main(LogBatDongBo.java:54)

Bốn dòng, đọc là hiểu. Giờ ném đúng nó từ trong một chuỗi compose có đi qua một bộ định giờ:

do sau: 20 khung
  lab.LogBatDongBo.hamC(LogBatDongBo.java:48)
  lab.LogBatDongBo.hamB(LogBatDongBo.java:47)
  lab.LogBatDongBo.hamA(LogBatDongBo.java:46)
  lab.LogBatDongBo.lambda$main$0(LogBatDongBo.java:65)
  io.vertx.core.impl.VertxImpl$InternalTimerHandler.handle(VertxImpl.java:1092)
  io.vertx.core.impl.ContextImpl.emit(ContextImpl.java:342)
  ... 14 khung nua cua Vert.x va Netty ...
  io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)

Hai mươi khung, trong đó bốn là mã của tôi và mười sáu là ống dẫn của Vert.x với Netty. Nhưng cái mất mới quan trọng hơn cái thừa: trong hai mươi khung đó không có gì cho biết chuỗi compose nào đã dẫn tới đây, và tuyệt đối không có gì cho biết request nào của người dùng đã châm ngòi.

Ngăn xếp cuộc gọi trong Java ghi lại ai gọi tôi trên luồng này, ngay lúc này. Trong mã bất đồng bộ, người đăng ký callback và người chạy callback là hai thời điểm khác nhau, nên phần lịch sử bạn cần đã bị vứt đi từ lâu.

Không có cách nào lấy lại nó rẻ tiền. Cách thực dụng là đừng dựa vào stack trace để biết ngữ cảnh — hãy tự mang ngữ cảnh theo, đúng như trace id ở phần 32:

log.error("that bai khi xu ly don hang, vetId={} donHangId={}", xem(), donHangId, e);

Hai trường đó nói được nhiều hơn cả hai mươi khung kia cộng lại.

Ngoại lệ đắt 0,39 µs, chủ yếu vì stack trace

new RuntimeException (co stack trace)   : 0,39 µs
new RuntimeException (KHONG stack trace): 0,01 µs

Gấp 39 lần. Gần như toàn bộ chi phí của một ngoại lệ nằm ở việc Java dựng lại ngăn xếp cuộc gọi. Với ngoại lệ dùng cho luồng điều khiển bình thường — "không tìm thấy", "hết lượt thử lại", "hết ngân sách thời gian" — mà stack trace vốn vô dụng như đã thấy ở trên, bạn tắt được nó:

static class LoiNhe extends RuntimeException {
    LoiNhe(String m){ super(m, null, false, false); }   // khong ghi de, khong stack trace
}

Đừng làm vậy với ngoại lệ báo lỗi thật — ở đó stack trace vẫn là thứ đầu tiên bạn nhìn.

Chi phí ghi log: gần như bằng không, trừ một trường hợp

200 kết nối, 8 giây mỗi đường, và tôi đếm số dòng log thật sự được ghi để chắc chắn nó có chạy:

Dòng cuối là dòng đáng ngạc nhiên: ghi 4,4 triệu dòng log trong 8 giây — hơn nửa triệu dòng mỗi giây — không tốn gì đo được so với không ghi gì. Vì đó là ghi có đệm vào page cache của hệ điều hành, và trong phép đo này hệ điều hành thừa sức nuốt.

Trường hợp duy nhất tốn tiền là immediateFlush=true: chậm 12%. Và đây là chỗ đáng chú ý — tôi đọc thẳng giá trị mặc định từ thư viện:

FileAppender.immediateFlush mac dinh = true

Cấu hình mặc định chính là cấu hình chậm. Mỗi dòng log là một lời gọi flush() xuống hệ điều hành. Đổi lại, bạn được đảm bảo là log đã ra khỏi tiến trình trước khi nó chết — đó là lý do mặc định như vậy, và với nhiều hệ thống thì 12% là cái giá xứng đáng để không mất mấy dòng log cuối cùng trước lúc sập.

Bốn giá trị mặc định biến log thành điểm chết

Đọc từ thư viện:

AsyncAppender.queueSize           = 256
AsyncAppender.discardingThreshold = -1     (nghia la 20% cua queueSize)
AsyncAppender.neverBlock          = false

Ba con số này gặp nhau tạo ra một hành vi mà tôi nghĩ ít người biết. Tôi dựng một appender cố tình chậm — 1 mili giây cho mỗi dòng, mô phỏng đĩa nghẽn hoặc bộ gom log từ xa đang chậm — rồi bắn tải:

Hai hàng cuối là hai kết cục hoàn toàn khác nhau của cùng một cấu hình.

Với INFO, thông lượng không hề giảm — vì Logback vứt gần hết log đi. Khoảng 916 000 request được phục vụ, 5 564 dòng được ghi: 99,4% bị bỏ, im lặng, không một cảnh báo nào. Đó là do discardingThreshold = -1, nghĩa là khi hàng đợi đầy 80% thì mọi sự kiện mức INFO, DEBUG và TRACE bị vứt thẳng.

Nghe qua thì có vẻ hợp lý — thà mất log còn hơn chậm dịch vụ. Nhưng hãy để ý khi nào nó vứt: lúc hệ thống đang bận. Tức là đúng những lúc bạn cần log nhất thì log không có ở đó, và bạn sẽ đi tìm dòng log của sự cố mà không hiểu vì sao nó biến mất.

Với ERROR thì Logback không được phép vứt — và cấu hình mặc định neverBlock = false nghĩa là khi hàng đợi đầy, nó chặn luồng gọi. Luồng gọi ở đây là event loop. Kết quả: 108 315 xuống 720 req/s, giảm 150 lần, p50 nhảy lên 380,9 ms.

Ghép hai điều đó lại thành một kịch bản rất thật: hệ thống chạy êm nhiều tháng. Một hạ nguồn hỏng, ứng dụng bắt đầu ghi ERROR với tốc độ cao. Bộ gom log chậm lại vì cũng đang nhận nhiều hơn thường lệ. Hàng đợi 256 phần tử đầy trong chớp mắt, và chính đoạn mã ghi log về sự cố lại nhân sự cố lên gấp 150 lần.

Cấu hình tôi sẽ dùng cho một ứng dụng Vert.x:

<appender name="BAT-DONG-BO" class="ch.qos.logback.classic.AsyncAppender">
  <queueSize>8192</queueSize>          <!-- 256 la qua nho -->
  <discardingThreshold>0</discardingThreshold>  <!-- dung vut INFO khi ban -->
  <neverBlock>true</neverBlock>        <!-- tha mat log con hon chan event loop -->
  <appender-ref ref="TEP"/>
</appender>
<appender name="TEP" class="ch.qos.logback.core.FileAppender">
  <immediateFlush>false</immediateFlush>
  ...
</appender>

neverBlock=true là đánh đổi có chủ ý: bạn chọn mất log thay vì mất dịch vụ. Với một ứng dụng event loop thì đó gần như luôn là lựa chọn đúng, vì một event loop bị chặn không chỉ làm hỏng request đang ghi log mà làm hỏng mọi request khác trên cùng loop — đúng như vách ngăn ở phần 31 và consumer Kafka ở phần 36 đã cho thấy.

Và nếu bạn chọn neverBlock=true, hãy đếm số log bị mất. Logback không tự báo, nên chỉ số đó phải do bạn tự thêm — nếu không bạn lại rơi vào đúng cái bẫy im lặng ở trên, chỉ là ở mức ERROR.

Thử ba mươi giây

Xem cấu hình log của bạn có phải quả bom hẹn giờ không:

grep -A5 'AsyncAppender' src/main/resources/logback.xml

Không thấy queueSize, discardingThreshold và neverBlock thì bạn đang chạy 256 / vứt-INFO / chặn-luồng — đúng bộ ba đã cho ra 720 req/s ở trên.

Và kiểm chứng bằng một phép thử thật, không cần dựng appender chậm: tạm chuyển appender sang ghi vào một ổ đĩa mạng hoặc thêm một Thread.sleep(1) như tôi đã làm, rồi bắn tải và ghi log ở mức ERROR. Nếu thông lượng sụp, bạn vừa tìm ra chỗ mà sự cố tiếp theo sẽ được nhân lên.

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