GC log nhìn như bức tường số vô nghĩa — nhưng ba con số nói cho bạn biết heap chật hay đang rò rỉ

Hãy nghĩ về vạch thuỷ triều. Lúc triều xuống thấp nhất, biển rút đi hết những gì rút được, để lộ đúng cái nền đá luôn nằm đó. Nếu mỗi lần triều xuống mà mực nền lại cao hơn lần trước, bạn biết nước đang tràn vào đâu đó. Full GC chính là lúc triều xuống của một ứng dụng Java: nó dọn sạch mọi thứ dọn được, và con số còn lại sau nó là cái nền đá thật. Nắm được một hình ảnh đó thôi là đã đọc được nửa cái GC log.

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ợ — một bức tường số và chữ viết tắt. Bài này gỡ từng phần. (Mọi con số dưới đây đo trên máy tôi với JDK 21, G1; tuyệt đối thì tuỳ tải và tuỳ máy, nhưng hình dạng mới là thứ đáng đọc.)

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ỉ" — chính là mực nền đá lúc triều xuống ở đầu bài.

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ụ — nước đang tràn vào — 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. Muốn tự chạy ngay câu thứ hai: grep "Pause Full" gc.log | grep -oE '[0-9]+M->[0-9]+M', rồi 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 cả heap mới dám kết luận.

Mẫu số chung

Cái vạch thuỷ triều không phải chuyện riêng của JVM — mọi runtime có bộ thu gom rác đều phát ra một dấu vết GC, và mẹo "đọc mực nền sau lần dọn toàn bộ" áp được y nguyên ở mọi nơi. Go có GODEBUG=gctrace=1, in mỗi chu kỳ một dòng kèm heap trước/sau và thời gian dừng — cùng ba con số, cùng cách đọc; heap-live sau mỗi chu kỳ cứ trèo lên là bạn có rò rỉ (thường là goroutine kẹt hoặc slice giữ mảng lớn). Node/V8 bật --trace-gc cho từng dòng scavenge và mark-sweep, và cái nền không rút xuống được là dấu hiệu closure hoặc map giữ tham chiếu. .NET có ETW và dotnet-gcdump, cùng khái niệm Gen 0/1/2 song ánh với Young/Survivor/Old. Ngay cả Python — vốn đếm tham chiếu là chính — cũng có module gc để soi số đối tượng vòng lặp không dọn được.

Điểm chung, và là thứ đáng mang theo: con số duy nhất phân biệt "chật" với "rò rỉ" trên mọi nền tảng là vùng sống sau một lần dọn toàn bộ — vì chỉ lần dọn đó mới rút hết những gì rút được, để lộ cái nền thật. Chật thì cái nền phẳng ở mức cao, chỉ cần thêm bộ nhớ; rò rỉ thì cái nền trèo lên mãi, và thêm bộ nhớ chỉ mua thêm vài ngày trước khi sập. Lẫn hai cái đó là sai lầm vận hành tốn kém nhất quanh GC: đội thì cấp gấp đôi RAM cho một chỗ rò rỉ và tuần sau lại sập, đội thì đi truy rò rỉ cho một heap thật ra chỉ hơi chật. Cùng một dòng log trả lời được cả hai — nếu bạn biết nhìn vào mực triều xuống.

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.