Chẩn đoán production: thread dump, heap dump, JFR

Đây là kỹ năng phân biệt người "biết JVM" với người "từng trực production". Nguyên tắc: thu bằng chứng trước, restart sau. Restart xóa sạch hiện trường. Bài này gom bộ công cụ và một playbook cho 3 triệu chứng.

1. Bài toán

02:07 Alert: order-service p99 = 4.2s (SLO 300ms)
       CPU pod: 100% (limit 2 CPU)
       Error rate: 3% timeout từ gateway

2. Vấn đề

• Metric chỉ nói có chuyện, không nói dòng code nào.
• Restart ngay thì mất thread state, heap state; 3 ngày sau lặp lại.
• Một số tool (heap dump) dừng app vài giây: phải biết tool nào an toàn.

3. Giải pháp: bộ công cụ

4. Từng bước

Bước 1: chuẩn bị trước sự cố (làm một lần)

# Dockerfile: dùng image có jcmd (JDK) hoặc thêm jdk.jcmd khi jlink
JAVA_TOOL_OPTIONS="-XX:+UseG1GC -XX:MaxRAMPercentage=75
  -Xlog:gc*:file=/var/log/app/gc.log:time,uptime:filecount=5,filesize=20m
  -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/dumps
  -XX:StartFlightRecording=name=bg,maxage=6h,maxsize=500m,settings=default"
# K8s: vào pod bằng
$ kubectl exec -it order-service-7d9c-xk2 -- bash
# hoặc kubectl debug --target=app để có tool mà không phình image

Trong container, process Java thường là PID 1 (bài 16.6), và jcmd phải chạy cùng user với app.

Bước 2: CPU 100% → thread nào?

$ top -H -p 1
  PID USER  %CPU  COMMAND
   87 app   98.7  http-nio-8080-e
   88 app   97.9  http-nio-8080-e
   23 app   12.0  G1 Conc#0
$ printf '%x\n' 87
57
$ jcmd 1 Thread.print > /tmp/td1.txt; sleep 5; jcmd 1 Thread.print > /tmp/td2.txt
$ grep -A 12 'nid=0x57' /tmp/td1.txt
"http-nio-8080-exec-12" #87 daemon prio=5 os_prio=0 tid=0x... nid=0x57 runnable
   java.lang.Thread.State: RUNNABLE
	at java.util.regex.Pattern$Loop.match(Pattern.java:5113)
	...
	at com.shop.order.validation.PromoCodeValidator.isValid(PromoCodeValidator.java:21)

Cùng stack trong cả 2 dump → thread kẹt ở regex (catastrophic backtracking với promo code dài). Nếu thread bận là G1 Conc/GC Thread thì CPU đang đổ vào GC → nhảy sang nhánh RAM.

Bước 3: API chậm, CPU thấp → thread đang chờ gì?

$ grep 'java.lang.Thread.State' /tmp/td1.txt | sort | uniq -c
    180 java.lang.Thread.State: WAITING (parking)
     15 java.lang.Thread.State: RUNNABLE
      5 java.lang.Thread.State: BLOCKED (on object monitor)

"http-nio-8080-exec-44" WAITING (parking)
	at jdk.internal.misc.Unsafe.park
	at com.zaxxer.hikari.util.ConcurrentBag.borrow(ConcurrentBag.java:151)
	at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:181)
→ 180 thread chờ connection DB: pool cạn (bài 6.8) hoặc query chậm giữ connection

Found one Java-level deadlock:
"exec-3": waiting to lock monitor 0x...(a com.shop.order.Inventory), which is held by "exec-9"
"exec-9": waiting to lock monitor 0x...(a com.shop.order.Order),     which is held by "exec-3"

Bước 4: profile bằng JFR và async-profiler

# JFR: dump bản ghi nền 6h gần nhất, mở bằng JDK Mission Control
$ jcmd 1 JFR.dump name=bg filename=/dumps/incident.jfr
$ jfr print --events jdk.ExecutionSample /dumps/incident.jfr | head
# hoặc ghi 2 phút có profile chi tiết
$ jcmd 1 JFR.start name=hot duration=120s settings=profile filename=/dumps/hot.jfr

# async-profiler: flame graph CPU 30 giây
$ asprof -d 30 -e cpu -f /tmp/cpu.html 1
$ asprof -d 30 -e alloc -f /tmp/alloc.html 1    # ai cấp phát nhiều
$ asprof -d 30 -e wall -t -f /tmp/wall.html 1   # thời gian thực, kể cả chờ I/O

Đọc flame graph:
 trục X = tỷ lệ mẫu (KHÔNG phải thời gian), trục Y = độ sâu stack
 tìm "cao nguyên" rộng ở đỉnh = code tự tiêu tốn CPU
┌──────────────────────────────────────────────────────────────┐
│     Pattern$Loop.match  (62%)            │ jackson write (9%) │
├──────────────────────────────────────────┼────────────────────┤
│     PromoCodeValidator.isValid            │ OrderController    │
├──────────────────────────────────────────┴────────────────────┤
│                 DispatcherServlet.doDispatch                    │
└────────────────────────────────────────────────────────────────┘

Bước 5: RAM tăng → GC log, histogram, heap dump

$ grep 'Pause' /var/log/app/gc.log | tail -5     # heap sau GC có tăng dần?
$ jcmd 1 GC.class_histogram | head -15            # lấy 2 lần cách 15 phút, so sánh
$ jcmd 1 GC.heap_dump /dumps/order-$(date +%s).hprof   # STW: rút pod khỏi LB trước
$ kubectl cp order-service-7d9c-xk2:/dumps/order-1760400000.hprof ./  # máy được phép

Rồi phân tích bằng MAT như bài 2.5.

5. Playbook: API chậm / CPU 100% / RAM tăng dần

                 ┌──────────── Alert ─────────────┐
                 │ 0. Giảm thiệt hại: scale out,   │
                 │    rollback nếu vừa deploy      │
                 │    GIỮ 1 pod lỗi lại (bỏ khỏi   │
                 │    LB: đổi label) để điều tra   │
                 └───────────────┬─────────────────┘
       ┌─────────────────────────┼──────────────────────────┐
       ▼                         ▼                          ▼
  API CHẬM                   CPU 100%                   RAM TĂNG DẦN
  1. Trace: chậm ở span      1. top -H: thread nào      1. Đó là heap hay RSS?
     nào? (DB/HTTP/app)         (app hay GC thread?)       (Actuator jvm.memory vs
  2. CPU thấp? → 3 thread    2. GC thread → nhánh RAM      container_memory)
     dump cách 5s, đếm       3. App thread: nid hex →   2. GC log: heap SAU GC
     state                      thread dump ×2–3           tăng dần? → leak
  3. Nhiều WAITING ở pool    4. async-profiler -e cpu   3. histogram ×2, so sánh
     → pool cạn / downstream    30s → flame graph       4. heap dump (rút LB) → MAT
     chậm / thiếu timeout    5. Hay gặp: regex,         5. Non-heap tăng? → NMT
  4. BLOCKED → lock / dead-     vòng lặp vô hạn,           (metaspace, thread,
     lock                       serialize lớn, GC          direct buffer)
  5. GC log: pause dài?         thrashing               6. OOMKilled? → so sánh
     → bài 2.4                                             limit vs heap (16.6)
       └─────────────────────────┼──────────────────────────┘
                                 ▼
          Fix + test tái hiện + thêm metric/alert + postmortem

6. So sánh: thread dump, heap dump, JFR, async-profiler

7. Khi nào dùng / không dùng

• Luôn: GC log + JFR nền + HeapDumpOnOOM bật sẵn, rẻ và cứu bạn lúc 2 giờ sáng.
• Thread dump: mọi sự cố "treo/chậm". Lấy ít nhất 2–3 lần cách vài giây; một lần không phân biệt được "kẹt" với "đang đi qua".
• Không chụp heap dump trên pod đang nhận traffic chính, và không khi disk không đủ chỗ.
• Không dùng jmap -histo:live bừa: nó ép Full GC.

Đúng, đọc tuần tự thì ngợp. Mẹo là nhóm và so sánh:

1. Đếm theo state (lệnh uniq -c ở trên). Tỷ lệ bất thường lộ ra ngay.
2. Chỉ xem thread của app (http-nio-*, kafka-consumer-*, pool của bạn). Bỏ qua thread JVM (GC Thread, C2 CompilerThread, Reference Handler).
3. Nhóm theo frame đầu tiên thuộc package com.shop: 150 thread cùng kẹt một dòng = thủ phạm.
4. So 2–3 dump: thread nào giữ nguyên stack qua các lần là kẹt thật.
5. Tìm từ khóa: Found one Java-level deadlock, - locked <0x...> và - waiting to lock <0x...> cùng địa chỉ.

Upload lên tool như fastthread.io giúp nhóm tự động, nhưng chỉ khi chính sách công ty cho phép. Với virtual threads, dùng jcmd 1 Thread.dump_to_file -format=json /tmp/vt.json vì jstack không liệt kê virtual thread (bài 3.11).

Chúng bổ sung cho nhau:

Thực tế: JFR luôn bật để có "hộp đen máy bay" của 6 giờ gần nhất; khi cần một flame graph CPU thật chính xác thì chạy async-profiler 30–60 giây. Spring Boot cũng xuất metric startup/JVM qua Actuator, gom về Prometheus/Grafana để thấy xu hướng trước khi cần tới tool nặng.

Q1. Service Java dùng 100% CPU, bạn điều tra thế nào?

🇻🇳 Tiếng Việt:

Em giữ lại một instance lỗi, rút khỏi load balancer để không mất hiện trường. Dùng top -H tìm thread OS tốn CPU, đổi thread id sang hex, rồi lấy hai ba thread dump bằng jcmd Thread.print cách nhau vài giây và tìm nid đó. Nếu là thread GC thì vấn đề là bộ nhớ, em chuyển sang GC log và heap. Nếu là thread của app thì em chạy async-profiler hoặc JFR khoảng 30 giây để có flame graph chỉ ra method tốn CPU, ví dụ regex backtracking hay vòng lặp vô hạn.

🇬🇧 English:

I keep one affected instance and take it out of the load balancer to preserve the evidence. I use top -H to find the hot OS threads, convert the thread id to hex, then take two or three thread dumps with jcmd Thread.print a few seconds apart and look up that nid. If it is a GC thread, the real problem is memory, so I move to GC logs and the heap. If it is an application thread, I run async-profiler or JFR for about thirty seconds to get a flame graph showing the hot method, such as regex backtracking or an infinite loop.

Q2. API chậm nhưng CPU thấp, bạn nghi gì?

🇻🇳 Tiếng Việt:

Thread đang chờ chứ không tính toán. Em xem trace để biết chậm ở span nào, rồi lấy thread dump và đếm theo state. Nhiều thread WAITING ở HikariPool.getConnection nghĩa là pool cạn hoặc query chậm; nhiều thread RUNNABLE ở socketRead nghĩa là gọi downstream không có timeout; nhiều BLOCKED là lock contention hoặc deadlock. Cũng kiểm tra GC log xem có pause dài không.

🇬🇧 English:

Threads are waiting rather than computing. I check traces to see which span is slow, then take thread dumps and count threads by state. Many threads WAITING in HikariPool.getConnection means the pool is exhausted or queries are slow; many RUNNABLE in socketRead means a downstream call without a timeout; many BLOCKED means lock contention or a deadlock. I also check GC logs for long pauses.

Q3. Production nên bật sẵn những gì để chẩn đoán?

🇻🇳 Tiếng Việt:

GC log xoay vòng, JFR chạy nền với maxage vài giờ, HeapDumpOnOutOfMemoryError ghi ra volume, và metric JVM qua Actuator, Micrometer lên Prometheus. Image cần có jcmd hoặc dùng kubectl debug. Những thứ này gần như không tốn chi phí nhưng giúp phân tích sự cố mà không phải chờ nó tái diễn.

🇬🇧 English:

Rotating GC logs, a background JFR recording with a few hours of max age, HeapDumpOnOutOfMemoryError writing to a volume, and JVM metrics through Actuator and Micrometer into Prometheus. The image should include jcmd, or we use kubectl debug. These cost almost nothing but let us analyze an incident without waiting for it to happen again.

Cách nhớ ngắn gọn

• Bằng chứng trước, restart sau; giữ một pod lỗi.
• CPU cao: top -H → hex nid → thread dump → flame graph.
• Chậm, CPU thấp: thread dump đếm state (WAITING pool, BLOCKED lock).
• RAM tăng: GC log → histogram ×2 → heap dump → MAT.
• Bật sẵn: GC log, JFR nền, HeapDumpOnOOM, metric.

Tổng kết chương 2: JVM