GC log là nguồn thông tin rẻ nhất về sức khoẻ một ứng dụng Java: bật gần như miễn phí, chạy được trên máy chủ thật, và trả lời được những câu mà biểu đồ CPU không trả lời nổi.

Vấn đề là nó trông đáng sợ. Bài này gỡ từng phần.

Bật cho đúng

# hằng ngày, chi phí gần bằng không, để luôn trong sản xuất
-Xlog:gc

# khi đang điều tra
-Xlog:gc*,gc+heap=debug

# ghi ra tệp, xoay vòng, giữ 5 tệp mỗi tệp 20MB
-Xlog:gc*:file=/var/log/app/gc.log:time,uptime,level,tags:filecount=5,filesize=20M

Tôi khuyên bật -Xlog:gc thường trực trên sản xuất. Nó ghi vài dòng mỗi giây, và khi sự cố xảy ra lúc 2 giờ sáng, có log là khác biệt giữa "biết ngay" và "phải tái hiện".

Lưu ý cho ai đọc tài liệu cũ: -XX:+PrintGCDetails, -XX:+PrintGCDateStamps, -Xloggc: đều đã bị bỏ từ Java 9. Chúng vẫn chạy nhưng in cảnh báo, và một ngày nào đó sẽ biến mất.

Giải phẫu một dòng

[0.345s][info][gc] GC(46) Pause Young (Normal) (G1 Evacuation Pause) 173M->162M(256M) 2.679ms

Đọc từ trái sang:

[0.345s] — thời điểm tính từ lúc JVM khởi động.

GC(46) — số thứ tự chu kỳ. Cùng một số có thể xuất hiện ở nhiều dòng, vì một chu kỳ đồng thời có nhiều giai đoạn.

Pause — chữ quan trọng nhất. Có Pause nghĩa là ứng dụng đứng im. Dòng không có chữ đó (Concurrent Mark Cycle) là GC làm việc song song, ứng dụng vẫn chạy.

Young / Mixed / Full — dọn vùng trẻ, dọn trẻ kèm một ít vùng già, hay dọn toàn bộ.

173M->162M(256M) — trước GC dùng 173MB, sau còn 162MB, tổng heap 256MB. Cặp số này là thứ đáng nhìn nhất trong cả dòng.

2.679ms — thời gian.

Ba con số cần nhìn trước tiên

Một: tỷ lệ thời gian dừng

Cộng mọi dòng có chữ Pause, chia cho thời gian chạy.

Và đây là chỗ tôi tự mắc lỗi khi làm bài này. Lần đầu tôi cộng mọi con số có đuôi ms trong log, và nhận kết quả 104,8% — GC chiếm hơn 100% thời gian, điều vô lý.

Nguyên nhân: tôi cộng cả các pha đồng thời, vốn chạy song song với ứng dụng chứ không dừng nó. Tách ra thì con số hợp lý ngay:

  chạy 0,27s | DỪNG 118,4ms (44,5%) | pha đồng thời 134,1ms

Bài học: chỉ cộng dòng có chữ Pause. Pha đồng thời tốn CPU chứ không tốn thời gian của ứng dụng.

Ngưỡng tôi dùng: dưới 5% là khoẻ, 5–10% đáng xem, trên 10% là có vấn đề cần xử lý.

Hai: vùng sống sau mỗi Full GC

Đây là con số quyết định để phân biệt "heap hơi chật" với "có rò rỉ".

Tôi chạy ba kịch bản và trích số sau mỗi Full GC:

  khoẻ mạnh   :  92  94  94                  <- phẳng
  heap chật   : 140 147 150 151 152          <- nhích dần rồi ổn định
  rò rỉ       : 237 249 252 252 252 -> OutOfMemoryError

Full GC dọn được mọi thứ có thể dọn. Nên con số sau nó chính là vùng sống thật.

Phẳng nghĩa là ứng dụng khoẻ. Tăng đều đặn và không bao giờ quay lại nghĩa là có thứ gì đó tích tụ — và đó là định nghĩa của rò rỉ bộ nhớ.

Dòng thứ ba cho thấy hình dạng cuối cùng: vùng sống chạm trần heap, mỗi Full GC dọn được gần như không gì, rồi OutOfMemoryError. Trước lúc đó, ứng dụng đã chậm kinh khủng vì GC chạy liên tục mà không thu được gì — người dùng cảm nhận sự cố trước khi log có dòng lỗi.

Ba: tần suất Full GC

Full GC với G1 nghĩa là nó đã bó tay và phải dọn toàn bộ heap trong một lần dừng dài.

Vài lần lúc khởi động là bình thường. Lặp lại đều đặn khi đã chạy ổn định thì luôn là dấu hiệu xấu — hoặc heap quá nhỏ, hoặc rò rỉ, hoặc có ai đó gọi System.gc().

Chi tiết đáng biết: nếu log ghi Pause Full (System.gc()) thì thủ phạm là mã của bạn hoặc một thư viện. Chặn bằng -XX:+DisableExplicitGC.

Heap bao nhiêu là đủ

Câu hỏi này trả lời được bằng đúng một bảng. Cùng tải, chỉ đổi -Xmx:

  heap     chạy      dừng     GC %   Young   Full   Evacuation Failure
  256m    0,29s   139,6ms    47,7%      36      3      3
  512m    0,22s    59,9ms    27,3%      19      0      0
  1g      0,20s    51,8ms    25,7%      14      0      0
  2g      0,20s    50,2ms    25,7%      13      0      0

Có một vách ngăn rõ ràng ở 512m: Full GC và Evacuation Failure cùng về 0, tỷ lệ GC giảm gần một nửa.

Và có một điểm bão hoà: từ 512m lên 2g, tỷ lệ GC chỉ nhích từ 27,3% xuống 25,7%. Bốn lần bộ nhớ để đổi lấy 1,6 điểm phần trăm.

Đây là cách tìm kích thước heap đúng, và nó tốt hơn mọi công thức: tăng dần cho tới khi Full GC về 0, rồi dừng lại. Cấp thêm nữa chỉ tốn RAM, và như bài 82 đã đo, RAM đó còn kéo theo cấu trúc GC lớn hơn.

Dấu hiệu heap quá nhỏ

Ba thứ xuất hiện cùng nhau, thấy trong cột của bảng trên:

Evacuation Failure — G1 muốn chép đối tượng sang vùng mới nhưng không còn vùng trống. Nó phải xử lý tình huống này bằng đường chậm, và đây là một trong những nguyên nhân gây dừng dài bất thường. Thấy chữ này là gần như chắc chắn cần thêm heap.

Full GC lặp lại khi đã chạy ổn định.

Khoảng cách giữa các lần Young GC ngắn dần — nghĩa là vùng trẻ bị co lại, thường vì vùng già đã chiếm gần hết heap.

Ngược lại, dấu hiệu heap quá lớn ít gặp hơn nhưng vẫn có: mỗi lần dừng rất lâu dù thưa, và RSS cao vô ích. Với G1 thì hiếm; với Parallel trên heap khổng lồ thì có thật.

Xem sâu hơn khi cần

-Xlog:gc+heap=debug

  region size 1024K, 23 young (23552K), 0 survivors (0K)
  Eden regions: 23->0(7)
  Survivor regions: 0->3(3)
  Old regions: 2->21

Ba dòng này cho thấy dòng chảy của đối tượng: Eden bị dọn sạch (23 về 0), 3 vùng sống sót sang Survivor, và Old tăng từ 2 lên 21 vùng.

Con số cần theo dõi là Old regions. Nó tăng đều sau mỗi chu kỳ nghĩa là đối tượng đang được đẩy lên vùng già nhanh hơn tốc độ dọn — hoặc do rò rỉ, hoặc do vùng trẻ quá nhỏ khiến đối tượng bị thăng cấp sớm.

Chú ý dòng Eden regions: 23->0(7): số trong ngoặc là kích thước Eden cho chu kỳ sau. G1 vừa co Eden từ 23 vùng xuống 7 — nó đang cố đạt mục tiêu tạm dừng, đúng cơ chế ở bài 85.

Bốn câu hỏi để chẩn đoán nhanh

Khi ai đó đưa bạn một GC log và hỏi "có vấn đề gì không", tôi rà theo thứ tự này:

Tỷ lệ Pause trên tổng thời gian là bao nhiêu? Trên 10% thì có chuyện.

Vùng sống sau Full GC có tăng đều không? Có thì đi tìm rò rỉ, đừng tăng heap — tăng heap chỉ dời sự cố sang tuần sau.

Có Evacuation Failure hay Full lặp lại không? Có thì thêm heap.

Lần dừng lâu nhất là bao nhiêu, và có chấp nhận được không? Nếu không, đó là lúc đọc lại bài 86 về ZGC và Shenandoah.

Bốn câu đó phân loại được gần hết các sự cố GC tôi từng gặp, và không câu nào cần công cụ ngoài grep.

Thử ba mươi giây

Lấy GC log của ứng dụng bạn, rồi chạy:

grep "Pause Full" gc.log | grep -oE '[0-9]+M->[0-9]+M'

Nhìn cột số bên phải mũi tên qua các dòng. Phẳng là khoẻ; tăng đều là rò rỉ.

Ba mươi giây, một lệnh, và nó trả lời câu hỏi mà rất nhiều đội phải chụp heap mới dám kết luận.

Ngày mai: tìm rò rỉ bộ nhớ cho ra nhẽ — chụp heap, đọc nó, và lần ngược chuỗi tham chiếu đang giữ đối tượng lại.