JVM tools — jstack, jmap, jstat, JFR và async-profiler

3h sáng. Pager: "API p99 latency 5s (SLA 200ms), CPU pegged 100%". Bạn SSH vào server prod. App vẫn chạy, không log error. Heap stable. Vậy gì đang xảy ra?

Câu trả lời nằm trong JVM tools — toolkit đi kèm JDK cho phép chẩn đoán JVM đang chạy mà không restart, không deploy code mới. Trong vài phút bạn có thể:

• Liệt kê thread đang block / chạy → tìm thread loop infinite hoặc deadlock.
• Snapshot heap → tìm object leak.
• Profile CPU → tìm method ăn CPU bất thường.
• Capture event GC, JIT, lock contention → reconstruct timeline.

Đây là kỹ năng phân biệt junior với senior Java engineer. Junior đoán, restart, hy vọng. Senior dùng tool, tìm root cause trong 30 phút.

Bài này đi qua: jps (list process), jstack (thread dump), jmap (heap dump), jstat (GC metric), jcmd (Swiss-army knife), JFR (Java Flight Recorder — production profiler), async-profiler (flame graph), và MAT (heap dump analysis). Kết thúc với workflow debug điển hình: từ symptom đến root cause.

1. Analogy — Bộ đồ nghề thợ điện

Thợ điện không "nghe" tủ điện đoán hỏng — họ có dụng cụ đo:

• Multimeter (đo điện áp/dòng) — jps + jstat: đọc số liệu hiện tại.
• Camera nhiệt — jstack: chụp snapshot mọi "dây" (thread) đang nóng/lạnh, ai đang chờ ai.
• Đo dòng dài hạn (data logger) — JFR: ghi liên tục mọi event để phân tích sau.
• Oscilloscope — async-profiler: đo wave form chi tiết, thấy chính xác chỗ "spike".
• Tháo tủ kiểm linh kiện — jmap heap dump + MAT: xem từng "linh kiện" (object) trong tủ.

Mỗi tool có context phù hợp. Dùng nhầm tool = lãng phí thời gian. Vd jstack cho memory leak vô nghĩa — phải jmap.

2. jps — list JVM process

Đầu tiên cần biết PID của JVM đang chạy.

jps -l
# 12345 com.myapp.MainApplication
# 23456 org.gradle.launcher.daemon.bootstrap.GradleDaemon
# 34567 sun.tools.jps.Jps

jps -v
# 12345 MainApplication -Xms2g -Xmx4g -XX:+UseG1GC ...

Flag:

• -l: full class name hoặc path JAR.
• -v: JVM args.
• -m: main args.

jps chỉ thấy JVM cùng user. Sudo nếu cần thấy JVM khác user.

Container Docker: jps chạy ngoài container không thấy JVM trong container. Cần docker exec <container> jps.

3. jstack — thread dump

Dump trạng thái mọi thread. Câu trả lời cho "app hang", "high CPU 1 thread", "deadlock?".

jstack 12345 > thread-dump.txt

Output mẫu:

"http-nio-8080-exec-3" #45 daemon prio=5 os_prio=0 cpu=12345.67ms elapsed=3456.78s tid=0x00007f0c... nid=0x4567 waiting on condition  [0x00007f0c...]
   java.lang.Thread.State: WAITING (parking)
        at jdk.internal.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x000000076ab12345> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:341)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1623)
        at com.myapp.Service.process(Service.java:42)
        at com.myapp.Controller.handle(Controller.java:25)
        ...

Đọc:

• "http-nio-8080-exec-3": tên thread.
• #45 daemon prio=5: ID, daemon flag, priority.
• cpu=12345.67ms: tổng CPU time thread đã dùng.
• Thread.State: WAITING (parking): trạng thái hiện tại (RUNNABLE, BLOCKED, WAITING, TIMED_WAITING).
• Stack trace: từ top frame đi xuống.
• parking to wait for <0x...>: thread đợi lock này.

State quan trọng

• RUNNABLE: đang chạy hoặc ready chạy. Nhiều RUNNABLE → CPU bound.
• BLOCKED: đợi lock (synchronized). Nhiều BLOCKED cùng địa chỉ lock → contention.
• WAITING / TIMED_WAITING: đợi notify hoặc condition. Thường idle (pool worker đợi task).

Detect deadlock

jstack tự detect deadlock. Output:

Found one Java-level deadlock:
=============================
"Thread-1":
  waiting to lock monitor 0x00007f0c... (object 0x000000076ab1, a java.lang.Object),
  which is held by "Thread-2"
"Thread-2":
  waiting to lock monitor 0x00007f0c... (object 0x000000076bc2, a java.lang.Object),
  which is held by "Thread-1"

Java stack information for the threads listed above:
===================================================
"Thread-1":
        at com.myapp.Foo.method1(Foo.java:10)
        - waiting to lock <0x000000076ab1>
        at ...

Báo rõ thread nào, lock nào, ở đâu. Fix: change lock order hoặc dùng tryLock timeout.

High CPU 1 thread

# Tim thread an CPU cao
top -H -p 12345
# PID  USER   ...   %CPU
# 12399 luatnq  ...  98.7
# 12400 luatnq  ...   2.3

# Convert TID sang hex de match nid trong jstack
printf '%x\n' 12399
# 3057

# Tim thread voi nid=0x3057 trong dump
jstack 12345 | grep -A 30 'nid=0x3057'

Stack thread đó cho biết method nào loop / busy spin.

Triple dump pattern

Hang state có thể là snapshot 1 thread tạm dừng — không phải bug. Để confirm:

for i in 1 2 3; do jstack 12345 > dump-$i.txt; sleep 5; done
# So sanh dump-1, dump-2, dump-3
# Thread van o cung stack frame qua 15s -> stuck

Real bug: thread cùng stack frame qua 3 dump. Nếu dump khác nhau → thread đang làm việc, không stuck.

4. jmap — heap dump và stats

Heap histogram (live object count + size)

jmap -histo:live 12345 | head -20

Output:

 num     #instances         #bytes  class name
----------------------------------------------
   1:        500000      40000000  com.myapp.Order
   2:        500000      32000000  java.lang.String
   3:       1000000      16000000  java.util.HashMap$Node
   4:        500000      12000000  [B (byte array)
   ...

Top class theo size. Tìm leak: class lạ với count cao = candidate.

:live ép GC trước → chỉ thấy live object. Bỏ → thấy cả object chờ GC, noisy.

Heap dump (full snapshot)

jmap -dump:live,format=b,file=heap.hprof 12345

Dump 1 file .hprof chứa toàn bộ object trong heap. Size = heap size (vài GB cho production typical). Chậm vài giây — pause app trong khi dump.

-XX:+HeapDumpOnOutOfMemoryError config sẵn JVM dump tự khi OOM.

Mở file bằng:

• Eclipse MAT (Memory Analyzer Tool) — desktop, đầy đủ feature.
• VisualVM — bundled JDK.
• JDK Mission Control — production tool, có heap analyzer.

Tip: dump 2 lần cách nhau 5 phút, so sánh diff trong MAT — class tăng nhiều = leak candidate.

5. jstat — realtime metric

Theo dõi GC, class loading, JIT realtime.

GC overview

jstat -gc 12345 1000
# Sample mỗi 1000ms

S0C    S1C    S0U    S1U    EC       EU       OC        OU       MC      MU      CCSC   CCSU   YGC    YGCT     FGC   FGCT     GCT
8192.0 8192.0 0.0    7234.5 65536.0  45123.2  131072.0  78901.2  20480.0 19234.5 2048.0 1923.4 145    1.234    3     0.567    1.801
8192.0 8192.0 4521.3 0.0    65536.0  12345.6  131072.0  79123.4  20480.0 19234.5 2048.0 1923.4 146    1.245    3     0.567    1.812

Cột:

• S0C/S1C/EC/OC/MC: capacity (KB) Survivor 0, Survivor 1, Eden, Old, Metaspace.
• S0U/S1U/EU/OU/MU: used.
• YGC / YGCT: young GC count + total time.
• FGC / FGCT: full GC count + total time.
• GCT: total GC time.

Theo dõi OU tăng dần qua sample → old gen growing → leak hoặc promote rate cao.

Tính toán nhanh

jstat -gcutil 12345 1000
# S0     S1     E      O      M      CCS    YGC     YGCT    FGC    FGCT     GCT
# 0.00  88.31  68.85  60.20  93.92  91.83    145    1.234     3    0.567    1.801

-gcutil show % thay vì KB — dễ đánh giá health. O 60% healthy, O 95% red flag.

6. jcmd — Swiss-army knife

jcmd (Java 8+) thay nhiều tool cũ. Ưu tiên dùng jcmd trong production.

jcmd 12345 help                              # Liet ke command available
jcmd 12345 GC.heap_info                      # Heap stats hien tai
jcmd 12345 GC.run                            # Force GC (don't usually)
jcmd 12345 GC.class_histogram                # = jmap -histo
jcmd 12345 GC.class_stats                    # Per-class loaded info
jcmd 12345 Thread.print                      # = jstack
jcmd 12345 VM.flags                          # JVM flag effective
jcmd 12345 VM.system_properties              # System property
jcmd 12345 VM.uptime                         # JVM running time
jcmd 12345 VM.classloader_stats              # Loader stats - debug metaspace leak

JFR control:

jcmd 12345 JFR.start name=profile duration=60s filename=profile.jfr
jcmd 12345 JFR.dump name=profile filename=profile.jfr
jcmd 12345 JFR.stop name=profile

Native memory tracking:

java -XX:NativeMemoryTracking=summary MyApp
jcmd 12345 VM.native_memory summary
# Show malloc breakdown: heap, class, thread, code, GC, internal, ...

Quan trọng debug "JVM ăn nhiều memory hơn -Xmx" — show native memory breakdown.

7. JFR — Java Flight Recorder

JFR là production-grade profiler built-in JVM. Capture event (GC, JIT, lock, IO, allocation, exception) với overhead <1% — bật được trong production.

Lịch sử

JFR được Oracle ship trong JRockit (commercial JVM mua lại từ BEA), sau merge vào HotSpot. Open-source từ Java 11 (JEP 328).

Trước Java 11: cần Oracle JDK + license. Java 11+: free, mainline OpenJDK.

Khởi động JFR

Pre-recorded (continuous)

java -XX:StartFlightRecording=duration=60s,filename=profile.jfr MyApp

Record 60s từ khi JVM start, dump file.

On-demand

# Start recording
jcmd 12345 JFR.start name=mysession duration=120s filename=/tmp/profile.jfr

# Check status
jcmd 12345 JFR.check

# Stop early
jcmd 12345 JFR.stop name=mysession

Always-on profile

java -XX:StartFlightRecording=settings=profile,maxsize=200m,maxage=1h,disk=true MyApp

JFR ghi liên tục, giữ 1 giờ gần nhất hoặc 200MB. On-demand JFR.dump lấy snapshot — debug post-incident: "30 phút trước hệ thống lag, có pattern gì?".

Profile preset: default (low overhead), profile (more events, ~2% overhead). Custom preset qua .jfc file XML.

Phân tích JFR file

JDK Mission Control (JMC) — desktop tool free, mở .jfr file:

• Garbage Collections: list cycle, pause time, cause.
• Method Profiling: flame graph CPU usage.
• Memory Allocation: top allocation site (class, thread, method).
• Thread: pause, contention, lock wait.
• JVM Internal: compilation event, deoptimization.
• I/O: file read, network read latency.

JMC interactive — drill down từ summary đến exact stack trace + line number.

CLI alternative:

jfr print --events GarbageCollection,MetaspaceOOM profile.jfr

Event quan trọng

• jdk.GarbageCollection: mỗi GC cycle với cause + duration.
• jdk.AllocationOutsideTLAB: object alloc đặc biệt (large object) — tracking allocation hot.
• jdk.JavaMonitorWait / jdk.JavaMonitorEnter: thread đợi lock — contention analysis.
• jdk.Compilation / jdk.Deoptimization: JIT activity.
• jdk.SocketRead / jdk.SocketWrite / jdk.FileRead: I/O latency.
• jdk.ExceptionThrown: mỗi exception throw — debug "exception storm".

8. async-profiler — flame graph chi tiết

JFR overhead thấp, sample-based — đủ cho overview. Cần detail hot method? async-profiler (https://github.com/async-profiler/async-profiler) — open-source, không phải Oracle, profiling theo CPU sampling và allocation tracking.

# Profile 30s, output flame graph
asprof -d 30 -f /tmp/flame.html 12345

# CPU profile
asprof -e cpu -d 30 -f cpu.html 12345

# Allocation profile (where alloc happens)
asprof -e alloc -d 30 -f alloc.html 12345

# Lock profile (contention)
asprof -e lock -d 30 -f lock.html 12345

Flame graph HTML: stack visualization. Trục X = % time CPU, trục Y = stack depth. Method "wide" = ăn nhiều CPU. Click để zoom.

Pattern đọc:

• Plateau wide ở top: hot method dùng CPU thực sự.
• Tower cao: deep call chain — có thể inline opportunity.
• Multiple wide top: nhiều hot path — phân bổ optimize.

async-profiler ưu điểm vs JFR:

• Native stack: thấy JNI / native call (JFR chỉ Java frame).
• Flame graph beautiful: intuitive hơn JMC table.
• Allocation profiling chi tiết hơn: thấy chính xác alloc per method.

Dùng song song JFR (continuous, low overhead) + async-profiler (deep dive khi đã identify suspicious).

9. Eclipse MAT — heap dump analysis

Khi có heap leak, dump .hprof → mở MAT (Eclipse Memory Analyzer Tool).

Workflow điển hình

1. Generate dump:

   jmap -dump:live,format=b,file=heap.hprof 12345
   

   Hoặc auto: -XX:+HeapDumpOnOutOfMemoryError.

2. Open MAT → File → Open Heap Dump.

3. Run "Leak Suspects" report — MAT auto-analyze, suggest top leak candidate.

4. Histogram view: list class theo retained size (memory bị giữ vì class này).

   • Sort theo Retained Heap descending.
   • Class với retained > 50% heap = strong candidate.

5. Dominator Tree: object dominate (giữ) memory nhiều nhất. Drill down: Object X giữ 1GB → ai giữ X?

6. Find GC Roots: class nghi leak → "Path to GC Roots" → MAT show chain reference giữ object live.

   MyOrder (1.5 KB)
   └── elementData[42] of java.util.ArrayList (40 KB)
       └── orders field of com.myapp.OrderCache (instance)
           └── INSTANCE field of com.myapp.OrderCache (static)  ← GC root!
   

7. Identify root cause: static field OrderCache.INSTANCE.orders giữ ArrayList grow vô hạn → leak.

OQL — query heap

MAT có DSL giống SQL query heap:

SELECT s.value FROM java.lang.String s WHERE s.value.length > 1000

Tìm String dài bất thường — log message, query SQL build vô tận, etc.

10. Workflow debug điển hình

Symptom: API p99 5s, CPU 100%

# 1. Tim PID
jps -l

# 2. Top thread CPU
top -H -p <PID>
# Note nhung TID an CPU cao

# 3. Convert TID sang hex
printf '%x\n' <TID>

# 4. Thread dump
jstack <PID> > dump.txt

# 5. Tim thread voi nid=0x<hex>
grep -A 30 'nid=0x<hex>' dump.txt

# 6. Stack frame: thay method nao busy spin

Nếu nhiều thread → flame graph:

asprof -d 30 -f cpu.html <PID>
# Mo browser, find wide method top

Symptom: OOM Java heap space

# 1. Auto dump (config truoc khi crash)
JAVA_OPTS="-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/var/log/heap"

# 2. Sau crash, copy heap.hprof ve local
scp server:/var/log/heap/java_pid12345.hprof .

# 3. Mo MAT
# Run "Leak Suspects Report"
# Investigate top retained class

# 4. Look at GC roots holding suspicious instance
# Identify static field / cache / collection growing

Symptom: GC chạy liên tục, throughput thấp

# 1. jstat realtime
jstat -gcutil <PID> 1000

# Pattern xau:
# - YGC tang nhanh (vai giay 1 lan)
# - O% leo cao (~95%) lien tuc
# - FGC tang -> co full GC
# - GCT chiem >5% uptime

# 2. JFR capture allocation hot
jcmd <PID> JFR.start name=alloc duration=60s filename=alloc.jfr

# 3. Mo JMC, Memory Allocation tab
# - Top allocation method
# - Allocation rate

# 4. Refactor code: cat alloc thua (string concat trong loop, intermediate stream object, vong loop tao throw-away object)

Symptom: app hang, không response

# 1. Triple dump confirm hang
for i in 1 2 3; do
    jstack <PID> > dump-$i.txt
    sleep 5
done

# 2. Diff dump
diff dump-1.txt dump-2.txt

# 3. Check deadlock
grep "Found one Java-level deadlock" dump-1.txt

# 4. Check tat ca thread state
grep "Thread.State" dump-1.txt | sort | uniq -c
# Nhieu BLOCKED -> contention
# Tat ca WAITING -> deadlock luc nha hoac cho external event

# 5. Tim lock contention
grep -A 5 "BLOCKED" dump-1.txt | grep "waiting to lock"

11. Pitfall tổng hợp

❌ Nhầm 1: Restart trước khi capture diagnosis.

Production hang -> restart -> mat thread state -> khong root cause

✅ Capture jstack + jmap (nếu RAM cho phép) trước restart.

❌ Nhầm 2: Heap dump trên production đang serve traffic.

jmap -dump 12345   # Pause app vai giay

✅ Drain traffic / fail-over trước. Hoặc trigger qua -XX:+HeapDumpOnOutOfMemoryError (chỉ khi đã OOM).

❌ Nhầm 3: Đọc thread dump 1 lần.

1 dump = snapshot 1 thoi diem. Co the thread tinh co o stack do, khong stuck.

✅ Triple dump, so sánh.

❌ Nhầm 4: Bỏ qua JFR vì nghĩ "tốn performance".

JFR overhead <1% production-grade. Bat always-on co loi hon overhead.

✅ Always-on JFR với rotation 1 giờ là standard production setup.

❌ Nhầm 5: Cài MAT trên production.

MAT cần GUI, chiếm RAM ngang heap dump (load full).

✅ Copy .hprof về dev machine, MAT local.

❌ Nhầm 6: Chỉ dùng jstack cho mọi vấn đề.

Memory leak -> jstack vo nghia. CPU high -> jstack thieu chi tiet method.

✅ Match tool với symptom (mục 10).

❌ Nhầm 7: Tin số jstat cho trend dài hạn.

jstat sample tung thoi diem, khong tat ca event GC.

✅ JFR cho long-term, jstat cho realtime quick check.

12. 📚 Deep Dive Oracle

13. Tóm tắt

• jps -lv: list JVM process với args.
• jstack <pid>: thread dump. State: RUNNABLE, BLOCKED, WAITING. Tự detect deadlock.
• Triple dump (3 lần cách 5s) confirm thread thực sự stuck.
• High CPU 1 thread: top -H -p <pid> → TID hex → match nid trong jstack.
• jmap -histo:live <pid>: count + size per class. Tìm leak candidate.
• jmap -dump:live,format=b,file=heap.hprof <pid>: full heap dump. Pause app vài giây.
• -XX:+HeapDumpOnOutOfMemoryError: auto dump khi OOM.
• jstat -gcutil <pid> 1000: realtime % usage. Old > 95% red flag.
• jcmd thay nhiều tool cũ. jcmd <pid> help list command. Ưu tiên dùng.
• JFR (Java Flight Recorder): production profiler, overhead <1%. Always-on với rotation 1 giờ.
• JMC (Mission Control): GUI phân tích .jfr file — GC, allocation, lock contention, exception, IO.
• async-profiler: flame graph CPU + allocation + lock. Native stack support. Dùng song song JFR.
• Eclipse MAT: heap dump analyzer. "Leak Suspects" report tự suggest. Dominator Tree show object retain memory nhiều. Path to GC Roots tìm chain leak.
• Workflow CPU 100%: top -H → jstack → identify hot method.
• Workflow OOM: heap dump (auto) → MAT → leak suspect → trace GC roots.
• Workflow GC liên tục: jstat → JFR → JMC allocation hot → refactor cut alloc.
• Workflow hang: triple jstack → diff → grep BLOCKED / WAITING / deadlock.
• Container: docker exec <container> jcmd ... để chạy tool trong namespace JVM.
• Capture diagnostic trước khi restart — restart mất state.

14. Tự kiểm tra

asprof -e cpu -d 30 -f /tmp/cpu.html 12345
# Mo /tmp/cpu.html trong browser
# Wide method top = hot path

# Healthy
S0     S1     E      O      M      YGC    YGCT    FGC    FGCT
0.00  88.31  68.85  60.20  93.92    145    1.234     3    0.567
0.00  88.50  70.12  60.85  93.92    146    1.245     3    0.567

# Red flag - O lien tuc tang, FGC nhieu
0.00  88.31  68.85  85.20  93.92    145    1.234     8    2.567
0.00  90.50  70.12  90.85  93.92    146    1.245    12    4.123
0.00  92.50  72.12  95.20  93.92    147    1.256    18    7.890
# FGC tang nhanh = pressure -> sap OOM

Thread X:
Dump 1: BLOCKED, waiting on lock 0xABC, frame: Service.process(L42)
Dump 2: BLOCKED, waiting on lock 0xABC, frame: Service.process(L42)
Dump 3: BLOCKED, waiting on lock 0xABC, frame: Service.process(L42)
=> Thread stuck waiting lock 0xABC suot 15s -> contention real

Thread Y:
Dump 1: RUNNABLE, frame: ArrayList.add(L100)
Dump 2: RUNNABLE, frame: HashMap.put(L200)
Dump 3: RUNNABLE, frame: String.equals(L80)
=> Thread dang lam viec binh thuong qua nhieu method -> khong stuck

Thread Z:
Dump 1: RUNNABLE, frame: MyService.compute(L50)
Dump 2: RUNNABLE, frame: MyService.compute(L50)
Dump 3: RUNNABLE, frame: MyService.compute(L50)
=> Stuck o 1 method -> infinite loop hoac hot spin

# Diff state count
for f in dump-*.txt; do
  echo "=== $f ==="
  grep "Thread.State" "$f" | sort | uniq -c
done

# Diff specific thread
diff <(grep -A 10 'http-nio-8080-exec-1' dump-1.txt) \
   <(grep -A 10 'http-nio-8080-exec-1' dump-2.txt)

for i in 1 2 3; do
  jstack <PID> > /tmp/dump-$i.txt
  sleep 5
done
echo "Captured 3 dumps in /tmp/"

Bài tiếp theo: Mini-challenge: Debug memory leak với JFR và heap dump