Câu hỏi quen thuộc khi một hệ thống chậm: "chậm ở đâu?" Câu trả lời quen thuộc: thêm log, đo bằng System.nanoTime(), đoán.

Có hai công cụ trả lời câu đó tử tế hơn nhiều, và cả hai đều rẻ tới mức chạy được trên sản xuất.

JFR tốn bao nhiêu

Đây là con số quyết định có nên bật thường trực hay không. Tôi chạy bảy lần mỗi cấu hình:

  không ghi   : min 269 ms | trung vị 278 ms | max 318 ms
  JFR profile : min 271 ms | trung vị 288 ms | max 333 ms

Trung vị chênh 10 ms trên 278 — khoảng 3,6%. Cấu hình default thì thấp hơn nữa, nằm dưới ngưỡng nhiễu của phép đo.

Tệp ghi cũng nhỏ:

  settings=default : 290 KB
  settings=profile : 344 KB

Hơn ba trăm kilobyte cho toàn bộ dữ liệu của một lần chạy. Với ứng dụng thật thì tính bằng megabyte mỗi giờ, và JFR có sẵn cơ chế xoay vòng.

Ba phần trăm là cái giá rất rẻ để đổi lấy việc khi sự cố xảy ra, bạn đã có dữ liệu. Không phải tái hiện, không phải chờ nó xảy ra lần nữa. Với tôi đây là lập luận mạnh nhất cho việc bật JFR mặc định trong sản xuất.

Bật cho đúng

# ghi liên tục, giữ 6 giờ gần nhất trong bộ nhớ vòng
-XX:StartFlightRecording=name=lientuc,settings=profile,maxage=6h,maxsize=200m

# khi có sự cố, kết xuất ra tệp
jcmd <pid> JFR.dump name=lientuc filename=/tmp/suco.jfr

# hoặc ghi một đoạn 60 giây rồi dừng
jcmd <pid> JFR.start duration=60s filename=/tmp/60s.jfr settings=profile

Kiểu dùng tôi khuyên là bộ nhớ vòng: JFR ghi liên tục nhưng chỉ giữ vài giờ gần nhất, và bạn chỉ kết xuất khi cần. Không tốn đĩa, và luôn có sẵn lịch sử ngay trước lúc sự cố.

Nó ghi những gì

jfr summary /tmp/b.jfr

  jdk.GCPhaseParallel                 3889
  jdk.PromoteObjectInNewPLAB          1531
  jdk.BooleanFlag                      498
  jdk.TenuringDistribution             270
  jdk.ObjectAllocationSample           120
  jdk.MetaspaceChunkFreeListSummary     80

Hơn 150 loại sự kiện, phủ gần hết những gì các bài trước của sê-ri đã bàn: GC (bài 85–87), nạp lớp (bài 81), biên dịch JIT (bài 84), ghim luồng ảo (bài 79), khoá tranh chấp, I/O tệp và mạng, ngoại lệ.

Điểm mạnh riêng của JFR là tương quan: mọi sự kiện dùng chung một trục thời gian, nên bạn trả lời được câu "lúc request chậm đó thì GC đang làm gì" — thứ mà ghép ba tệp log lại rất khó làm.

Ví dụ với sự kiện cấp phát:

  objectClass = java.util.HashMap$KeyIterator
  weight      = 20.4 MB
  eventThread = "main"
  stackTrace  = [ ... ]

Nó cho cả khối lượng lẫn ngăn xếp — đủ để đi thẳng tới dòng mã.

Đọc bằng công cụ dòng lệnh jfr print --events <tên> tep.jfr, hoặc mở bằng JDK Mission Control nếu muốn giao diện đồ hoạ.

async-profiler: thứ JFR không thấy

JFR chỉ thấy khung Java. async-profiler thấy cả khung native, và khác biệt đó rất rõ trong kết quả thật:

       ns  percent  samples  top
  ----------  -------  -------  ---
   470000000   48,96%       47  Lau.xuLy
   200000000   20,83%       20  Lau.cham
    50000000    5,21%        5  libc.so.6
    20000000    2,08%        2  G1ScanHRForRegionClosure::scan_heap_roots
    10000000    1,04%        1  PhaseChaitin::Simplify
    10000000    1,04%        1  java.lang.Integer.getChars

Hai dòng cuối là điểm mấu chốt. G1ScanHRForRegionClosure::scan_heap_roots là bộ thu gom rác; PhaseChaitin::Simplify là trình biên dịch C2. Đây là mã của chính JVM, và JFR không bao giờ hiện chúng ra.

Nghĩa là async-profiler trả lời được câu hỏi "thời gian CPU đi đâu" một cách trọn vẹn — kể cả khi câu trả lời là "GC" hoặc "JIT đang biên dịch", chứ không chỉ "mã của bạn".

Nó cũng dùng lấy mẫu không an toàn điểm dừng, tránh được thiên lệch điểm an toàn — một sai lệch kinh điển làm các profiler cũ chỉ ra nhầm hàm.

Hồ sơ cấp phát tìm ra một phép đóng hộp

       bytes  percent  samples  top
  7352600888   95,99%    14024  byte[]
   303562173    3,96%      579  java.lang.Integer
     2097148    0,03%        4  java.util.LinkedHashMap$Entry

byte[] 7,35 GB là dự kiến — chương trình cố tình cấp mảng byte.

Nhưng dòng thứ hai là thứ tôi không viết ra: 303 MB java.lang.Integer.

Nguồn của nó là một dòng trông vô hại:

cache.put(i % 50_000, new byte[300]);    // i % 50_000 là int -> đóng hộp thành Integer

Khoá của map là Integer, nên mỗi lần put là một lần Integer.valueOf. Giá trị vượt 127 nên không dùng được bộ nhớ đệm (đúng chuyện ở bài 70), và mỗi lần là một đối tượng mới.

Ba trăm megabyte rác từ một dấu ngoặc. Đây đúng là loại thứ mà đọc mã không bao giờ thấy, còn hồ sơ cấp phát thì chỉ mặt trong ba giây.

Biểu đồ ngọn lửa

async-profiler xuất trực tiếp ra HTML, nhưng đáng biết định dạng trung gian:

  Lau.main;Lau.xuLy 45
  Lau.main;Lau.xuLy;Lau.cham 8
  Lau.main;Lau.xuLy;zero_blocks 7

Mỗi dòng là một ngăn xếp cộng số mẫu. Biểu đồ ngọn lửa chỉ là cách vẽ bảng này.

Cách đọc, gói trong ba câu:

Chiều ngang là thời gian, không phải thứ tự. Ô càng rộng càng tốn nhiều CPU. Trục ngang được sắp theo bảng chữ cái, nên đừng đọc nó như dòng thời gian.

Chiều dọc là độ sâu ngăn xếp. Dưới là hàm gọi, trên là hàm bị gọi.

Tìm những cao nguyên rộng ở phía trên. Một ô rộng ở đỉnh nghĩa là hàm đó tự nó tốn CPU. Một ô rộng ở dưới mà chia nhỏ ở trên thì chi phí nằm rải rác trong các hàm con.

Sai lầm hay gặp là nhìn vào ô rộng nhất ở đáy — nó luôn là main và chẳng nói gì cả.

Một lưu ý khi chạy trong container

Chỗ này tôi vấp thật khi làm bài. Chế độ mặc định event=cpu của async-profiler cần perf events của hạt nhân, mà container thường không cấp:

  Could not start attach mechanism / không có tệp kết quả

Hai cách xử lý:

# cách một: đổi sang bộ đếm thời gian, không cần quyền gì thêm
-agentpath:libasyncProfiler.so=start,event=itimer,file=/tmp/cpu.txt

# cách hai: cấp quyền cho container
docker run --cap-add SYS_ADMIN ...
# hoặc trên máy chủ: sysctl kernel.perf_event_paranoid=1

itimer kém chính xác hơn một chút và không thấy được thời gian trong hạt nhân, nhưng nó chạy ở mọi nơi và đủ dùng cho phần lớn việc.

Ngoài ra, nạp agent lúc khởi động bằng -agentpath đáng tin hơn gắn vào sau bằng asprof — cơ chế gắn hay hỏng trong container, và đây cũng là cách cấu hình hồ sơ liên tục trong sản xuất.

Và nhớ -XX:+UnlockDiagnosticVMOptions -XX:DebugNonSafepoints để ngăn xếp không bị sai do nội tuyến hoá.

Chọn cái nào

Cần Dùng
Bật suốt, phòng khi có sự cố JFR, settings=profile, bộ nhớ vòng
Tương quan GC với độ trễ request JFR
Biết CPU đi đâu, kể cả vào GC và JIT async-profiler
Tìm chỗ cấp phát nhiều cả hai, async-profiler chi tiết hơn
Biểu đồ ngọn lửa async-profiler
Không được cài thêm gì lên máy chủ JFR — nó nằm sẵn trong JDK

Trong thực tế tôi dùng cả hai: JFR chạy nền thường trực, async-profiler bật lên khi cần đào sâu.

Thử ba mươi giây

Thêm dòng này vào lệnh khởi động ứng dụng của bạn:

-XX:StartFlightRecording=settings=profile,maxage=2h,maxsize=100m,name=lientuc

Chi phí khoảng ba phần trăm, và lần tới khi có ai hỏi "lúc 3 giờ sáng hệ thống bị gì", bạn có jcmd <pid> JFR.dump name=lientuc filename=/tmp/3h.jfr thay vì phải nói "để tôi thêm log rồi chờ nó xảy ra lần nữa".

Ngày mai: đo hiệu năng cho đúng bằng JMH — vì sao mọi phép đo tự viết đều sai, và những cạm bẫy nó xử lý hộ bạn.