Bật hồ sơ suốt ngày chỉ tốn 3,6% — để 3 giờ sáng có sẵn dữ liệu thay vì phải chờ sự cố xảy ra lần nữa

Có hai cách tìm ra vì sao một hệ thống chậm. Cách thứ nhất là bộ camera an ninh chạy suốt ngày đêm, âm thầm ghi lại mọi thứ với chi phí gần bằng không — khi có chuyện lúc 3 giờ sáng, bạn đã có sẵn cuốn băng, khỏi phải dựng lại hiện trường. Cách thứ hai là mang tới một máy chụp X-quang nhìn xuyên được cả những lớp mà camera không thấy — không chỉ sản phẩm chạy trên dây chuyền, mà cả bộ máy bên dưới. JDK Flight Recorder là cái camera; async-profiler là cái máy X-quang. Bài này về cả hai, và cả hai đều rẻ tới mức chạy được trên sản xuất.

Câu hỏi quen thuộc khi một hệ thống chậm là "chậm ở đâu?", và câu trả lời quen thuộc — thêm log, đo bằng System.nanoTime(), đoán — chính là thứ hai công cụ này thay thế. (Số đo dưới đây trên máy tôi; tỷ lệ mới là thứ đáng đọc.)

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.

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ố — đúng cái camera chạy vòng, ghi đè băng 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. Đây là bộ xương mà chỉ máy X-quang nhìn thấy.

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

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.

Muốn bắt đầu ngay trong ba mươi giây: thêm -XX:StartFlightRecording=settings=profile,maxage=2h,maxsize=100m,name=lientuc vào lệnh khởi động. 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".

Mẫu số chung

Cái camera-chạy-suốt và cái X-quang-nhìn-xương không phải đặc sản của Java — mọi runtime trưởng thành đều có một bộ hồ sơ lấy mẫu chi phí thấp, đủ rẻ để bật trên sản xuất. Go đóng gói sẵn pprof trong thư viện chuẩn: gắn net/http/pprof là có ngay hồ sơ CPU, heap, khối chặn, tranh chấp mutex — đúng tinh thần "JFR nằm sẵn trong JDK", và cũng là lấy mẫu. Linux perf cộng biểu đồ ngọn lửa là gốc gác của cả thể loại này (async-profiler xuất ra định dạng tương thích với nó). .NET có dotnet-trace trên EventPipe — bản song sinh của JFR: dựng sẵn, chi phí thấp, ghi liên tục được. Node thì --prof của V8 và clinic.js. Và cả một ngành "hồ sơ liên tục" (Pyroscope, Parca, Grafana) mọc lên quanh đúng ý tưởng ấy: đừng đợi sự cố mới đo.

Điểm chung, và là thứ đáng mang theo, gồm hai câu hỏi và một kỷ luật. Hai câu hỏi mà mọi profiler ở mọi ngôn ngữ đều trả lời: "CPU đi đâu" — bằng lấy mẫu ngăn xếp rồi vẽ thành biểu đồ ngọn lửa, đọc theo ô rộng ở phía trên chứ không phải ô rộng ở đáy — và "cấp phát đến từ đâu" — bằng hồ sơ heap, thứ chỉ mặt được cả những phép đóng hộp giấu trong một dấu ngoặc. Còn kỷ luật, là thứ tách người đoán mò khỏi người biết chắc: bật hồ sơ trước khi sự cố xảy ra, không phải sau. Ba phần trăm chi phí để lúc nào cũng có sẵn cuốn băng là món hời ở bất kỳ ngôn ngữ nào — vì cái đắt nhất trong gỡ lỗi hiệu năng chưa bao giờ là chi phí đo, mà là phải ngồi chờ một sự cố hiếm xảy ra lần thứ hai.

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.