Continuous profiling JVM: flame graph trên production

Đây đúng là chỗ trace dừng lại và profile bắt đầu. Trace cho biết span nào chậm, profile cho biết hàm nào trong span đó tốn thời gian. Cách chạy JFR/async-profiler bằng tay lúc sự cố đã ở Chẩn đoán JVM production. Bài này nói về chạy liên tục và đọc flame graph.

1. Bài toán

payment-service sau bản 3.2: p99 tăng từ 250ms lên 900ms, CPU mỗi Pod tăng 40%, HPA scale từ 4 lên 9 Pod (tốn tiền). Không có exception nào. Không tái hiện được ở local vì dữ liệu nhỏ.

2. Vấn đề

• Profile bằng tay lúc 2 giờ sáng: phải exec vào Pod, chạy đúng lúc sự cố, Pod có thể đã bị thay.
• Không có "trước" để so với "sau": không biết hàm nào mới tốn hơn.
• Metric và trace chỉ tới mức span; bên trong span là hộp đen.
• Profiler kiểu instrument từng method (như debugger) chậm gấp nhiều lần, không chạy được trên prod.

3. Giải pháp: sampling profiler chạy liên tục

Sampling profiler cứ ~10ms chụp stack trace của các thread, đếm stack nào xuất hiện nhiều. Overhead thường 1–2%, đủ thấp để bật 24/7. Dữ liệu gửi về một backend lưu theo thời gian, như metric.

Công cụ: JFR (có sẵn trong JDK, overhead ~1%), async-profiler (không bị safepoint bias, thấy cả native/kernel frame), backend Pyroscope / Grafana Profiles để lưu và so sánh.

4. Code từng bước

Bước 1: Pyroscope Java agent trong Deployment

env:
- name: JAVA_TOOL_OPTIONS
  value: >-
    -javaagent:/otel/opentelemetry-javaagent.jar
    -javaagent:/pyroscope/pyroscope.jar
- name: PYROSCOPE_APPLICATION_NAME
  value: payment-service
- name: PYROSCOPE_SERVER_ADDRESS
  value: http://pyroscope.monitoring:4040
- name: PYROSCOPE_PROFILER_EVENT
  value: itimer                    # CPU; trong container không cần perf_events
- name: PYROSCOPE_PROFILER_ALLOC
  value: 512k                      # lấy mẫu mỗi 512KB cấp phát
- name: PYROSCOPE_PROFILER_LOCK
  value: 10ms                      # ghi lock chờ > 10ms
- name: PYROSCOPE_LABELS
  value: env=prod,version=3.2

Agent này dùng async-profiler bên trong. Label version giúp so 3.1 với 3.2.

Bước 2: Nối profile với trace (span profiles)

<dependency>
  <groupId>io.pyroscope</groupId>
  <artifactId>otel</artifactId>
</dependency>

Thư viện này gắn span ID vào mẫu profile. Trong Grafana, mở trace ở Tempo → span payment.calculateFee → "Profiles for this span" ra flame graph chỉ của span đó.

Bước 3: JFR chạy liên tục (không cần agent ngoài)

# Thêm vào JAVA_TOOL_OPTIONS
-XX:StartFlightRecording=settings=default,maxage=6h,maxsize=500m,dumponexit=true,filename=/tmp/jfr/
-XX:FlightRecorderOptions=repository=/tmp/jfr

# Lúc cần: dump 30 phút gần nhất từ Pod đang chạy
kubectl exec payment-service-7c84c-abc12 -- jcmd 1 JFR.dump name=1 maxage=30m filename=/tmp/last30.jfr
kubectl cp shop/payment-service-7c84c-abc12:/tmp/last30.jfr ./last30.jfr
jfr print --events jdk.ExecutionSample last30.jfr | head
jfr summary last30.jfr        # mở bằng JDK Mission Control để xem đồ họa

JFR mặc định giữ bộ đệm vòng: luôn có dữ liệu của vài giờ vừa qua, không phải "chạy đúng lúc".

Bước 4: Đọc kết quả và sửa

So sánh (diff flame graph) version=3.1 với version=3.2 trong Grafana:

payment.calculateFee                        48% (3.1: 6%)
 └ FeeRuleEngine.match                      46%
    └ java.util.regex.Pattern.compile       41%   ← mới
       └ Pattern.<init> ...

// 3.2: compile regex trong mỗi lần gọi
boolean matches(String merchantCode) {
    return Pattern.compile(rule.regex()).matcher(merchantCode).matches();
}

// Sửa: compile một lần khi load rule
record FeeRule(String regex, BigDecimal rate, Pattern pattern) {
    FeeRule(String regex, BigDecimal rate) { this(regex, rate, Pattern.compile(regex)); }
    boolean matches(String code) { return pattern.matcher(code).matches(); }
}

# Kiểm chứng: chạy tải rồi so p99 và CPU
hey -z 60s -c 50 -m POST -H 'Content-Type: application/json' \
    -d '{"orderId":"1234","amount":99.0}' http://localhost:8080/payments/fee

5. Cách hoạt động: đọc flame graph

        ┌──────────────────────────────────────────────────────┐
  top   │ Pattern.compile ████████████████████   (plateau rộng) │ ← nơi CPU thật sự tiêu
        │ FeeRuleEngine.match █████████████████████            │
        │ calculateFee ███████████████████████████  │ JSON ███ │
        │ PaymentController.charge ████████████████████████████ │
        │ Tomcat / Thread.run ██████████████████████████████████ │ ← gốc
        └──────────────────────────────────────────────────────┘
  - Trục Y: độ sâu stack (gốc dưới, hàm lá trên).
  - Trục X: tỷ lệ mẫu, KHÔNG phải thời gian; thứ tự trái phải là alphabet.
  - Tìm "plateau": khung rộng ở đỉnh = hàm tự nó tốn nhiều (self time).
  - Khung rộng ở dưới nhưng phía trên chia nhỏ = chi phí rải ra nhiều nơi.

Liên kết 4 tín hiệu:
Alert p99 (metric) → exemplar → trace → span calculateFee 600ms
   → "Profiles for this span" → Pattern.compile 41% → sửa code

6. So sánh

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

• Bật continuous profiling cho service quan trọng hoặc tốn nhiều compute: thường trả lại tiền hạ tầng nhanh.
• Latency cao mà CPU thấp: xem wall-clock và lock, không phải CPU profile.
• GC pause cao: allocation profile chỉ ra hàm tạo rác, hiệu quả hơn tune GC.
• Không dùng profiler kiểu instrumentation (VisualVM "Profiler" tab) trên prod.
• Profile không thay được trace: nó gộp nhiều request, không biết request nào chậm.

Lo lắng hợp lý, nhưng với sampling profiler thì overhead thấp và đo được. Cách thuyết phục sếp là đo, không hứa:

• CPU sampling ~100 mẫu/giây: thường dưới 1–2% CPU. JFR profile default được thiết kế cho production, khoảng 1%.
• Allocation sampling: đặt ngưỡng (512KB), không ghi từng object. Đặt quá nhỏ mới gây tốn.
• Lock: chỉ ghi lần chờ vượt ngưỡng (10ms).
• Mạng: profile được nén và gửi mỗi 10–15 giây, vài KB/s mỗi Pod.

Kế hoạch an toàn:

1. Bật cho 1 Pod canary của payment-service (label version=canary)
2. So p99 và CPU canary với Pod khác trong 1–2 ngày
3. Nếu chênh < 2%, bật toàn bộ; nếu không, giảm tần suất hoặc tắt alloc/lock
4. Có công tắc: biến môi trường để tắt agent không cần build lại image

Đổi lại: lần đầu tìm ra một Pattern.compile như trên, HPA từ 9 Pod về 4 Pod, tiết kiệm nhiều hơn 2% rất nhiều.

Bạn đang xem wall-clock profile (hoặc CPU profile có tính cả thread chờ). Những frame đó là thread đang chờ, không phải đang làm việc. Cần đọc đúng loại:

Vậy:

1. Chuyển sang CPU profile để biết code có đốt CPU không.
2. Ở wall-clock, lọc chỉ thread request (http-nio-*), bỏ thread pool rảnh.
3. Nếu thread request chủ yếu chờ Hikari → vấn đề nằm ở DB/pool, không phải ở Java code. Đó cũng là một câu trả lời có giá trị.

Q1. Continuous profiling là gì, khác gì profile lúc có sự cố?

🇻🇳 Tiếng Việt:

Là chạy sampling profiler liên tục trên production với overhead khoảng 1–2%, gửi dữ liệu về backend như Pyroscope để lưu theo thời gian. Khác với profile thủ công, nó luôn có dữ liệu của thời điểm sự cố, kể cả khi Pod đã bị thay, và cho phép so sánh trước và sau một bản release. Nó cũng dùng để tối ưu chi phí, tìm hàm đốt CPU nhiều nhất trên toàn hệ thống.

🇬🇧 English:

It means running a sampling profiler constantly in production at around 1–2% overhead and shipping the data to a backend like Pyroscope that stores it over time. Unlike ad-hoc profiling, you always have data from when the incident happened, even if the Pod was replaced, and you can compare before and after a release. It's also used for cost optimization, finding the hottest functions across the fleet.

Q2. Đọc flame graph thế nào?

🇻🇳 Tiếng Việt:

Trục dọc là stack, gốc ở dưới, hàm lá ở trên. Trục ngang là tỷ lệ mẫu, không phải thời gian, và thứ tự trái phải không có ý nghĩa. Em tìm những khung rộng ở đỉnh, tức hàm có self time lớn. Em cũng chú ý loại profile: CPU cho biết đốt CPU, wall-clock gồm cả thời gian chờ, allocation cho biết tạo rác, lock cho biết tranh chấp.

🇬🇧 English:

The vertical axis is the stack, root at the bottom and leaf functions on top. The horizontal axis is the share of samples, not time, and left-to-right order means nothing. I look for wide frames at the top, which are functions with high self time. I also check the profile type: CPU shows what burns CPU, wall-clock includes waiting, allocation shows garbage creation, and lock shows contention.

Q3. Latency tăng nhưng CPU thấp, bạn dùng profile nào?

🇻🇳 Tiếng Việt:

CPU thấp nghĩa là thread đang chờ chứ không tính toán, nên CPU profile sẽ không thấy gì. Em dùng wall-clock và lock profile, lọc theo thread xử lý request, để thấy chúng chờ ở đâu: connection pool, lock, socket tới DB hay service khác. Rồi đối chiếu với trace và metric pool như Hikari pending.

🇬🇧 English:

Low CPU means threads are waiting rather than computing, so a CPU profile won't show much. I use wall-clock and lock profiles filtered to request threads to see where they wait: the connection pool, a lock, or a socket to the database or another service. Then I cross-check with traces and pool metrics like Hikari pending connections.

Q4. Làm sao nối profile với trace?

🇻🇳 Tiếng Việt:

Profiler gắn span ID hiện tại làm label cho mẫu, ví dụ thư viện Pyroscope OTel. Khi mở một span chậm trong Tempo, em xem flame graph chỉ của các mẫu thuộc span đó. Như vậy đường điều tra là metric alert, exemplar dẫn sang trace, span chậm dẫn sang profile, profile chỉ ra dòng code.

🇬🇧 English:

The profiler tags samples with the current span ID, for example via the Pyroscope OTel integration. When I open a slow span in Tempo I can view a flame graph of only the samples belonging to that span. So the investigation path is: a metric alert, an exemplar leading to a trace, the slow span leading to a profile, and the profile pointing at the line of code.

Cách nhớ ngắn gọn

• Trace: span nào chậm. Profile: hàm nào trong span.
• Sampling ~100Hz, overhead 1–2%: bật 24/7 được.
• CPU cao → CPU profile; chờ → wall/lock; GC → alloc.
• Flame graph: tìm khung rộng ở đỉnh; trục X không phải thời gian.
• So sánh version cũ/mới bằng diff flame graph.