99 Ngày Java — Ngày 75: Profiling & công cụ

Bốn ngày qua ta học bộ nhớ, GC, nạp lớp và JIT. Tất cả đều kết thúc ở một lời khuyên: đo, đừng đoán. Hôm nay là bộ công cụ để đo. Tin tốt: mọi thứ cần thiết đã có sẵn trong JDK 21 (jcmd, jfr, JFR, JDK Mission Control tải riêng) và VisualVM miễn phí. Ta dùng một chương trình cố tình có ba bệnh để tập trả lời ba câu hỏi: CPU đang đi đâu, bộ nhớ đang bị ai giữ, và các luồng đang chờ cái gì.

Profiling: JFR và jfr view, heap dump với MAT, thread dump, VisualVM và checklist triệu chứng → công cụ

1. Chương trình bệnh nhân

import java.util.*;
import java.util.concurrent.*;

// Chương trình có ba "bệnh" để tập chẩn đoán: tốn CPU vô ích, rò rỉ bộ nhớ, và luồng chờ nhau.
public class ProfilingDemo {
    static final Map<String, byte[]> CACHE = new HashMap<>();   // bệnh 2: chỉ thêm, không bao giờ bớt
    static final Object LOCK = new Object();

    static String slowKey(int i) {                              // bệnh 1: nối chuỗi trong vòng lặp
        String key = "";
        for (int k = 0; k < 200; k++) key += (char) ('a' + (i + k) % 26);
        return key;
    }

    public static void main(String[] args) throws Exception {
        ExecutorService pool = Executors.newFixedThreadPool(4, r -> new Thread(r, "worker"));
        for (int i = 0; ; i++) {
            final int n = i;
            pool.submit(() -> {
                String key = slowKey(n);
                synchronized (LOCK) {                            // bệnh 3: khóa quá rộng, 4 luồng xếp hàng
                    CACHE.put(key, new byte[16 * 1024]);
                    try { Thread.sleep(2); } catch (InterruptedException e) { Thread.currentThread().interrupt(); }
                }
            });
            Thread.sleep(1);
        }
    }
}
// Chạy: java -Xmx256m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=./oom.hprof ProfilingDemo.java

Chạy nó vài phút: CPU của bốn worker cao, heap tăng đều rồi OOM, và throughput thấp hơn nhiều so với bốn luồng đáng ra làm được. Ba triệu chứng, ba công cụ.

2. Java Flight Recorder: hộp đen chạy được trên production

# 1. Bật JFR trên tiến trình ĐANG CHẠY (không cần khởi động lại) — chi phí ~1–2%
jcmd <pid> JFR.start name=demo settings=profile duration=60s filename=demo.jfr

# hoặc ngay từ lúc khởi động:
java -XX:StartFlightRecording=settings=profile,duration=60s,filename=demo.jfr ProfilingDemo.java

# 2. Xem nhanh không cần GUI (Java 21 có 'jfr view' với ~70 view dựng sẵn)
jfr summary demo.jfr
jfr view hot-methods demo.jfr          # phương thức chiếm nhiều mẫu CPU nhất
jfr view allocation-by-class demo.jfr  # lớp nào cấp phát nhiều nhất
jfr view contention-by-site demo.jfr   # khóa nào bị tranh chấp, ở đâu
jfr view gc demo.jfr                   # từng lần GC: loại, pause, heap trước/sau

# 3. Đào sâu bằng GUI: JDK Mission Control (jmc) mở demo.jfr — flame graph, timeline, allocation

JFR được thiết kế cho production: lấy mẫu stack định kỳ thay vì đo từng lời gọi, nên chi phí thường dưới 2% và không làm méo kết quả như profiler instrumentation. Bật bằng jcmd trên tiến trình đang chạy, không cần restart.
jfr view hot-methods với ProfilingDemo sẽ chỉ thẳng slowKey và String.concat/StringBuilder: nối chuỗi trong vòng lặp tạo 200 chuỗi trung gian mỗi lần. allocation-by-class xác nhận bằng số byte cấp phát.
contention-by-site cho biết LOCK ở dòng nào bị tranh chấp và luồng chờ tổng bao lâu: đó là bệnh thứ ba, nhìn thấy mà không cần đọc thread dump.
Bản ghi settings=profile chi tiết hơn default (mẫu dày hơn, ngưỡng thấp hơn), vẫn an toàn cho vài phút trên production. Ghi liên tục với maxage=1h và jcmd <pid> JFR.dump khi sự cố xảy ra cho bạn một giờ lịch sử trước lúc có chuyện.
JDK Mission Control mở file .jfr với flame graph, timeline GC, phân bổ theo lớp, và trang “Automated Analysis” tự gợi ý vấn đề. Dùng khi jfr view chưa đủ.

3. Heap dump: ai đang giữ bộ nhớ

# Chụp heap của tiến trình đang chạy (chỉ object còn sống → đã ép một full GC, ứng dụng dừng vài giây)
jcmd <pid> GC.heap_dump ./live.hprof

# Hoặc tự động khi OOM — đặt sẵn trên MỌI service production, không tốn gì cho tới khi cần:
java -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/var/dumps/ App

# Thống kê nhanh không cần dump: lớp nào chiếm nhiều bộ nhớ nhất
jcmd <pid> GC.class_histogram | head -15
#  num     #instances         #bytes  class name
#    1:         41230      675545600  [B                 ← byte[] của CACHE
#    2:         41230        1319360  java.lang.String
# Đọc dump: Eclipse MAT → Leak Suspects · Dominator Tree · Histogram
# Retained size (giữ bao nhiêu nếu nó biến mất) mới là số cần nhìn, không phải shallow size.

Bắt đầu rẻ nhất bằng GC.class_histogram: nếu top 3 là byte[], String và một lớp của bạn, câu hỏi tiếp theo là ai giữ chúng. Histogram không trả lời được; heap dump thì có.
Trong Eclipse MAT, Dominator Tree sắp object theo retained size: CACHE sẽ đứng đầu vì xóa nó là giải phóng gần như toàn bộ heap. Leak Suspects tự tìm đúng kết luận đó trong vài giây. Từ object, chọn “Path to GC Roots” để thấy chuỗi tham chiếu: static field ProfilingDemo.CACHE → HashMap → mảng entry → byte[].
Dump chỉ object sống ép một full GC và dừng ứng dụng vài giây với heap vài GB; file dump lớn bằng heap. Trên production, ưu tiên -XX:+HeapDumpOnOutOfMemoryError đặt sẵn: không tốn gì cho tới khi cần, và khi OOM xảy ra bạn có bằng chứng thay vì phải tái hiện.
Heap dump chứa dữ liệu thật (mật khẩu trong String, token, dữ liệu khách hàng). Xử lý như dữ liệu nhạy cảm: không đính vào ticket công khai, xóa sau khi phân tích.

4. Thread dump: các luồng đang chờ gì

# Thread dump: mọi luồng đang làm gì NGAY LÚC NÀY
jcmd <pid> Thread.print > dump1.txt
# ...đợi 10 giây, chụp lại 2 lần nữa: luồng nào đứng yên qua cả 3 lần mới là vấn đề
"worker" #23 prio=5 ... waiting for monitor entry [0x...]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at ProfilingDemo.lambda$main$0(ProfilingDemo.java:20)
        - waiting to lock <0x000000070a0b1c20> (a java.lang.Object)     ← 3 luồng chờ cùng một LOCK
"worker" #22 ...
   java.lang.Thread.State: TIMED_WAITING (sleeping)
        at java.lang.Thread.sleep(...)
        - locked <0x000000070a0b1c20> (a java.lang.Object)               ← luồng đang giữ khóa

# Java 21: Thread.print KHÔNG liệt kê virtual thread — dùng dump dạng JSON:
jcmd <pid> Thread.dump_to_file -format=json ./threads.json

# Deadlock: JVM tự phát hiện, cuối dump có "Found one Java-level deadlock"

Một dump là ảnh chụp; ba dump cách nhau 10 giây mới là bằng chứng. Luồng BLOCKED ở cùng một dòng qua cả ba lần là nút thắt; luồng RUNNABLE ở cùng một stack là vòng lặp nóng hoặc I/O chậm đang chờ trong native.
Đọc từ dưới lên: dòng locked <0x...> cho biết ai giữ khóa, dòng waiting to lock <0x...> cho biết ai chờ. Cùng một địa chỉ xuất hiện ở nhiều luồng là dấu hiệu khóa quá rộng, như LOCK bao cả Thread.sleep trong ví dụ.
Với deadlock, JVM đã làm việc phân tích: cuối dump có Found one Java-level deadlock kèm vòng chờ. Ngày 66 đã tạo deadlock chủ ý; nay bạn biết bằng chứng trông thế nào.
Java 21 với virtual thread: Thread.print chỉ liệt kê platform thread. Dùng Thread.dump_to_file -format=json để thấy cả virtual thread, gom theo executor; đây là công cụ khi hàng nghìn virtual thread cùng chờ một tài nguyên.

5. VisualVM và checklist chọn công cụ

Triệu chứng                        → Công cụ đầu tiên
CPU cao, đáp ứng chậm              → JFR hot-methods / flame graph trong JMC
Bộ nhớ tăng dần, OOM               → GC log (Ngày 72) → GC.class_histogram → heap dump + MAT
Treo, throughput thấp mà CPU thấp  → 3 thread dump cách 10s; tìm BLOCKED / WAITING lặp lại
GC pause dài                       → jfr view gc · -Xlog:gc*
Chậm lúc khởi động                 → JFR từ lúc start · -Xlog:class+load (Ngày 73)
Muốn nhìn trực tiếp trên laptop    → VisualVM: Monitor · Sampler (CPU / Memory) · Threads

VisualVM (visualvm.github.io) tự thấy JVM cục bộ; tab Monitor cho heap/CPU/thread theo thời gian thực, tab Sampler lấy mẫu CPU và bộ nhớ với chi phí thấp, tab Threads là thread dump có màu. Đủ cho laptop; trên server hãy dùng JFR rồi tải file về.
Sampler (lấy mẫu định kỳ) và Profiler (instrument từng phương thức) khác nhau ở chi phí và độ méo: instrument làm phương thức nhỏ trông đắt hơn thật vì thêm mã đo vào chính nó. Mặc định dùng sampler; chỉ instrument khi cần đếm chính xác số lần gọi.
jstat -gcutil <pid> 1000 in tỷ lệ đầy của từng vùng heap mỗi giây: cách nhìn nhanh nhất để biết old gen có đang tăng không, trước khi mở bất kỳ file nào.
Thứ tự luôn là: triệu chứng → giả thuyết → công cụ đo đúng giả thuyết → sửa → đo lại. Mở profiler mà không có câu hỏi cụ thể là cách chắc nhất để tối ưu nhầm chỗ.

6. Tự kiểm tra

Chạy ProfilingDemo với JFR 60 giây; dùng jfr view hot-methods và contention-by-site để chỉ ra hai bệnh đầu trước khi đọc lại mã nguồn.
Để chương trình OOM với HeapDumpOnOutOfMemoryError; mở dump trong MAT, chạy Leak Suspects và tìm Path to GC Roots của mảng byte[] lớn nhất.
Chụp ba thread dump; đếm số luồng BLOCKED trên LOCK mỗi lần. Thu hẹp khóa (đưa sleep ra ngoài synchronized) và chụp lại.
Sửa slowKey dùng StringBuilder và đặt giới hạn cho CACHE; ghi lại JFR mới và so sánh hot-methods cùng allocation trước/sau.

Tóm lại: JFR là công cụ đầu tiên cho CPU, cấp phát và tranh chấp khóa, chạy được trên production; heap dump với MAT trả lời “ai giữ bộ nhớ” bằng retained size và đường tới GC root; ba thread dump trả lời “luồng chờ gì”; VisualVM đủ cho máy dev; và mỗi phiên đo bắt đầu bằng một câu hỏi. Ngày 76 quay lại heap với một lớp công cụ tinh tế hơn: Soft, Weak và Phantom reference, và cách viết cache không thành rò rỉ như CACHE hôm nay.

Tài liệu đối chiếu

JFR và lệnh jfr (Java 21): https://docs.oracle.com/en/java/javase/21/jfapi/ ; jcmd: https://docs.oracle.com/en/java/javase/21/docs/specs/man/jcmd.html ; JDK Mission Control: https://www.oracle.com/java/technologies/jdk-mission-control.html ; Eclipse MAT: https://eclipse.dev/mat/ ; VisualVM: https://visualvm.github.io/