Dùng log.debug("{}", x) vẫn tốn 37ms cho 2 triệu lần gọi — dù DEBUG đang tắt

Log là thứ duy nhất bạn có khi hệ thống hỏng lúc 2 giờ sáng. Bài này về cách viết log để lúc đó nó thật sự giúp được, và về cái giá của nó khi mọi thứ đang chạy bình thường.

Bốn cách gọi log, bốn con số

Hai triệu lần gọi log.debug, với mức DEBUG đang tắt:

  nối chuỗi              :  95 ms
  tham số {}             :  37 ms
  có isDebugEnabled()    :   4 ms
  API lười (fluent)      :   5 ms

Dòng thứ nhất ai cũng biết là sai: log.debug("gia tri = " + tonKem(i)) ghép chuỗi trước khi gọi, nên bạn trả tiền kể cả khi log bị tắt.

Dòng thứ hai mới là chỗ tôi muốn nhấn mạnh, vì nó thường được dạy như cách chữa:

log.debug("gia tri = {}", tonKem(i));

Cách này tránh được việc định dạng chuỗi. Nhưng tonKem(i) vẫn chạy — nó là đối số, và Java tính đối số trước khi gọi phương thức. 37 mili giây kia chính là hai triệu lần chạy một hàm mà không ai dùng kết quả.

Hai dòng cuối tránh được cả hai:

if (log.isDebugEnabled()) log.debug("gia tri = {}", tonKem(i));       // canh cổng
log.atDebug().addArgument(() -> tonKem(i)).log("gia tri = {}");        // API lười, SLF4J 2.x

Nhanh hơn hai mươi lần so với nối chuỗi.

Quy tắc thực dụng: dùng {} mặc định — nó đủ tốt khi đối số là biến sẵn có. Chỉ thêm canh cổng khi đối số cần tính toán — gọi hàm, duyệt danh sách, toString() của một đối tượng lớn, hay serialize JSON.

Log có cấu trúc

Cùng một sự kiện, hai định dạng:

  2026-08-11 04:32:44,861 INFO [req-abc-123] text - don hang 0 trang thai DA_GIAO

{"@timestamp":"2026-08-11T04:32:45.079Z","message":"don hang 0 trang thai DA_GIAO",
 "logger_name":"json","thread_name":"main","level":"INFO","maRequest":"req-abc-123"}

Khác biệt không nằm ở vẻ ngoài mà ở chỗ truy vấn được. Với JSON, maRequest là một trường thật, nên bạn lọc maRequest = "req-abc-123" để lấy toàn bộ dòng log của một request. Với văn bản, bạn phải viết biểu thức chính quy và cầu cho định dạng không đổi.

Cái giá:

  200.000 dòng log:
    văn bản, ghi thẳng   : 185 ms | tệp 34,0 MB
    JSON,    ghi thẳng   : 210 ms | tệp 40,5 MB
    văn bản, bất đồng bộ : 110 ms

JSON chậm hơn 13% và tốn thêm 19% dung lượng. Với thứ nó đổi lại, tôi thấy đó là món hời.

Cấu hình bằng Logback:

<appender name="JSON" class="ch.qos.logback.core.ConsoleAppender">
  <encoder class="net.logstash.logback.encoder.LogstashEncoder"/>
</appender>

Trong container, ghi ra stdout chứ đừng ghi ra tệp. Docker và Kubernetes đã thu log từ đó, và ghi tệp trong container nghĩa là tự lo xoay vòng, tự lo dung lượng, và mất log khi container bị xoá.

Bất đồng bộ: 110 ms so với 185 ms

<appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
  <queueSize>8192</queueSize>
  <discardingThreshold>0</discardingThreshold>
  <appender-ref ref="JSON"/>
</appender>

Nhanh hơn 40% vì luồng ứng dụng chỉ bỏ thông điệp vào hàng đợi rồi đi tiếp.

Hai tham số phải hiểu, vì mặc định của chúng có thể làm bạn mất log:

discardingThreshold mặc định là 20 — nghĩa là khi hàng đợi đầy 80%, Logback âm thầm vứt các thông điệp TRACE, DEBUG và INFO. Đặt về 0 để không vứt gì.

queueSize quyết định chịu được bao nhiêu khi đầu ra chậm. Hàng đợi đầy thì luồng ứng dụng bị chặn — đó là hành vi đúng (áp lực ngược, như bài 73), nhưng nghĩa là log chậm vẫn làm ứng dụng chậm.

Ba thứ phải có trước khi lên sản xuất

Một: mã tương quan trong mọi dòng log

Không có nó, log của một trăm request đồng thời trộn vào nhau và bạn không tách được.

MDC.put("maRequest", UUID.randomUUID().toString());
try {
    xuLy(request);
} finally {
    MDC.clear();          // BẮT BUỘC
}

MDC chạy trên ThreadLocal, nên mọi cảnh báo ở bài 78 đều áp dụng: quên clear() thì luồng trong pool mang mã của request cũ sang request mới, và bạn có log gán nhầm người dùng. Đặt put/clear trong một filter ở ngoài cùng, không rải rác trong mã nghiệp vụ.

Với luồng ảo thì bẫy này biến mất — mỗi tác vụ một luồng mới. Nhưng MDC không tự lan sang luồng con, nên khi bạn nộp việc vào executor, mã tương quan sẽ mất nếu không truyền tay.

Hai: chỉ số, không chỉ log

Log trả lời "chuyện gì đã xảy ra với request này". Chỉ số trả lời "hệ thống đang thế nào".

Bốn chỉ số tôi cho là tối thiểu:

Tỷ lệ lỗi theo endpoint. Độ trễ theo phân vị — p50, p95, p99, không phải trung bình. Bài 86 đã cho thấy trung bình giấu đi phần đuôi, mà phần đuôi mới là thứ người dùng cảm nhận. Thông lượng. Tài nguyên bão hoà — pool kết nối (bài 66), hàng đợi executor (bài 74), heap (bài 87).

Với Spring Boot, Micrometer cộng Actuator cho gần hết miễn phí:

@Timed(value = "don_hang.xu_ly", percentiles = {0.5, 0.95, 0.99})
public void xuLy(DonHang d){ ... }

Và như bài 89 đã đo, JFR chạy nền tốn khoảng 3% — nó bổ sung cho chỉ số bằng dữ liệu ở mức JVM.

Ba: truy vết phân tán

Với một dịch vụ, mã tương quan là đủ. Từ hai dịch vụ trở lên, bạn cần trace id đi xuyên qua các lời gọi — nếu không, request chậm 3 giây mà bạn không biết ba giây đó nằm ở dịch vụ nào.

OpenTelemetry là chuẩn hiện nay, và bản Java agent gắn được không cần sửa mã:

java -javaagent:opentelemetry-javaagent.jar \
     -Dotel.service.name=dich-vu-don-hang \
     -jar app.jar

Nó tự chèn ngữ cảnh vào lời gọi HTTP, truy vấn JDBC, và thông điệp Kafka.

Điều đáng làm ngay cả khi chưa có hệ thống truy vết: đưa trace id vào log. Lúc đó một dòng log dẫn thẳng tới toàn bộ đường đi của request qua mọi dịch vụ.

Ghi cái gì, và không ghi cái gì

Ghi ở ranh giới — request vào, lời gọi ra ngoài, thông điệp nhận được. Ở giữa thì để chỉ số lo.

Ghi ngữ cảnh, không ghi câu văn. "khong tim thay nguoi dung" vô dụng; log.warn("khong tim thay nguoi dung id={} trong {}", id, nguon) thì gỡ được.

Ghi ngoại lệ đúng cách:

log.error("khong luu duoc don hang {}", maDon, e);    // e là tham số CUỐI, không có {}

Đây là chỗ hay sai: viết log.error("loi: " + e.getMessage()) là mất dấu vết ngăn xếp — thứ duy nhất cho biết lỗi đến từ đâu.

Đừng ghi bí mật. Mật khẩu, token, số thẻ, dữ liệu cá nhân. CLAUDE.md của chính blog này có một mục về việc đó, sau khi mật khẩu quản trị từng bị in ra log lúc khởi động. Log container thường được gom về nơi khác và giữ rất lâu; ai đọc được log là đăng nhập được.

Đừng ghi trong vòng lặp nóng. Ngay cả với {}, hai triệu dòng log là 34 megabyte và 185 mili giây — và không ai đọc nổi.

Chọn mức cho đúng: ERROR là "cần người xử lý ngay", WARN là "bất thường nhưng đã xử lý được", INFO là "sự kiện nghiệp vụ đáng nhớ", DEBUG là để gỡ lỗi. Ghi ERROR cho thứ không cần ai làm gì là cách nhanh nhất để mọi người tắt cảnh báo.

Thử ba mươi giây

Tìm trong dự án của bạn:

grep -rn 'log\.\(debug\|trace\)(".*" *+' src/

Mỗi kết quả là một chỗ đang nối chuỗi trước khi gọi log — tốn công kể cả khi mức đó đã tắt. Và nếu chỗ đó nằm trong vòng lặp nóng, bảng đầu bài cho biết bạn đang trả bao nhiêu cho những dòng log không ai nhìn thấy.

Ngày mai — áp chót của sê-ri: những lỗ hổng bảo mật hay gặp trong ứng dụng Java, và quét phụ thuộc có lỗ hổng bằng OWASP Dependency-Check.