Safepoint và Stop-The-World — tại sao GC pause dài hơn GC log báo

TL;DR: Safepoint là vị trí trong execution nơi JVM biết hoàn toàn trạng thái mọi thread — mọi reference đều có thể được tìm thấy, không có operation nào đang dở. JVM yêu cầu mọi thread đến safepoint trước khi bắt đầu operation toàn cục (GC, deoptimization, JFR sample...). Time-to-safepoint (TTSP) là thời gian từ khi JVM request stop đến khi tất cả thread arrive. Thread đang chạy counted loop dài có thể không poll safepoint hàng chục ms, khiến TTSP spike dài hơn GC pause thực sự. GC log báo "20ms" nhưng app freeze 150ms vì TTSP 130ms trước đó.

Bài 05 giới thiệu GC pause như là thời gian STW (Stop-The-World). Thực tế đo được trên production đôi khi cho thấy app freeze dài hơn GC pause log nhiều. Khoảng chênh lệch đó là TTSP — thời gian "chờ mọi thread đến điểm an toàn". Bài này giải thích cơ chế safepoint, tại sao TTSP tồn tại, và cách diagnose.

1. Scenario — GC log báo 50ms nhưng app freeze 200ms

Team nhận alert SLA breach: latency p99 vượt 200ms. Kiểm tra GC log:

[info][gc] GC(42) Pause Young (Normal) 48.234ms
[info][gc] GC(43) Pause Young (Normal) 51.891ms

GC pause rõ ràng chỉ 50ms — không đủ gây breach. Nhưng trace từ user request cho thấy:

Request A: start 10:00:00.000, end 10:00:00.198  -> 198ms
GC(42):    start 10:00:00.020, end 10:00:00.068  -> 48ms (GC log)

Chênh lệch: request bị block từ 00:000 đến 00:068 = 68ms. Nhưng GC thực sự chỉ xảy ra từ 00:020 đến 00:068. Từ 00:000 đến 00:020 là gì?

Đó là khoảng thời gian JVM yêu cầu stop và chờ thread xử lý request A tự ngừng lại tại safepoint tiếp theo. Thread A chưa đến safepoint → GC chưa bắt đầu được. Thread A freeze nhưng GC chưa tính thời gian. GC log chỉ tính thời gian sau khi tất cả thread đã arrive.

Để hiểu toàn bộ latency, cần hiểu safepoint.

2. Safepoint — điểm execution biết toàn bộ

Safepoint là vị trí trong luồng thực thi (cụ thể là instruction) nơi JVM có thể xác định hoàn toàn trạng thái của thread — biết chính xác mọi object reference đang live ở đâu (stack frame, register), không có allocation đang dở, không có monitor acquisition đang dở.

Tại safepoint, GC có thể:

• Scan toàn bộ stack của thread để tìm GC root.
• Di chuyển (relocate) object mà không sợ đọc stale pointer.
• Cập nhật reference table an toàn.

JIT compiler chèn safepoint poll instruction tại các vị trí xác định trong compiled code:

• Method return (trước khi return về caller).
• Loop back-edge (mỗi lần vòng lặp quay lại điểm đầu).
• Allocation site (trước khi alloc object lớn).
• Native call boundary (khi gọi JNI native method).

// JIT compile method nay va chen safepoint poll
public void processItems(List<String> items) {
    for (String item : items) {   // <-- safepoint poll tai loop back-edge
        process(item);            // <-- safepoint poll tai method return
    }
}
// Khi JVM can stop: poll page bi protect -> thread nao hit poll se trap -> suspend

3. Cơ chế safepoint polling — hardware page protection trick

JIT không thực sự check 1 biến boolean mỗi lần poll — điều đó tốn quá nhiều. HotSpot dùng một trick cực kỳ thông minh với memory page protection:

Bình thường (fast path):

; x86 assembly - safepoint poll instruction
; polling_page la dia chi 1 memory page JVM giu
TEST RAX, QWORD PTR [polling_page]   ; 1 instruction, doc memory
; Neu page readable -> no-op (result bo di)
; Cost: 1 memory read, ~1-5 ns khi in cache

Khi JVM muốn stop tất cả thread:

JVM gọi OS để mark polling page là unreadable (page không còn accessible). Bất kỳ thread nào thực thi instruction TEST RAX, [polling_page] tiếp theo sẽ gây segfault / access violation. JVM đã cài signal handler để catch segfault này — khi nhận được signal, handler biết thread đó đã arrive safepoint và suspend thread.

sequenceDiagram
    participant VM as JVM Main Thread
    participant T1 as Thread 1
    participant T2 as Thread 2
    participant OS as OS Memory
    participant GC as GC Thread

    VM->>OS: mprotect(polling_page, PROT_NONE)
    Note over VM: polling_page now unreadable

    T1->>OS: TEST RAX, [polling_page]  (safepoint poll)
    OS-->>T1: SIGSEGV / segfault
    T1->>VM: Signal handler: "I arrived safepoint"
    VM-->>T1: Suspend thread 1

    T2->>OS: Still running counted loop...
    Note over T2: T2 has no back-edge poll for next 10ms
    T2->>OS: TEST RAX, [polling_page]  (eventually)
    OS-->>T2: SIGSEGV
    T2->>VM: Signal handler: arrived
    VM-->>T2: Suspend thread 2

    VM->>GC: All threads at safepoint - start GC
    GC->>GC: Scan roots, collect garbage
    VM->>OS: mprotect(polling_page, PROT_READ)
    VM->>T1: Resume
    VM->>T2: Resume

Chi phí của poll trong fast path: 1 memory read instruction, khoảng 1-5 ns khi polling page được cache. Overhead gần như zero cho app bình thường.

4. Stop-The-World — các operation cần STW

STW (Stop-The-World) là cơ chế JVM yêu cầu tất cả Java thread phải arrive safepoint và suspend, sau đó JVM thực hiện 1 global operation, rồi resume tất cả thread.

Các operation cần STW:

STW latency = TTSP + actual operation time. GC log thường chỉ report operation time (sau khi tất cả thread đã suspend).

5. Time-to-safepoint — tại sao TTSP quan trọng

Time-to-safepoint (TTSP) là khoảng thời gian từ khi JVM request safepoint (protect polling page) đến khi thread cuối cùng arrive. Trong thời gian này:

• Thread đã arrive: đã suspend, chờ.
• Thread chưa arrive: đang chạy code giữa 2 safepoint poll.
• JVM: chờ, không làm gì (kể cả GC chưa bắt đầu).
• App: request mới không được xử lý vì thread pool có thể đã bị lock chờ.

TTSP tệ nhất xảy ra khi 1 thread đang chạy code dài giữa 2 back-edge poll. Thread không gặp back-edge poll vì:

1. Counted loop được JIT optimize: for (int i = 0; i < N; i++) với N là int — JIT có thể xác định loop là counted loop (số lần chạy biết trước). Để tối ưu, JIT loại bỏ back-edge poll trong counted loop — chạy nhanh hơn nhưng TTSP tăng.

2. Loop body rất nhanh, N rất lớn: 100 triệu iteration × 1ns/iteration = 100ms loop không có poll = TTSP 100ms.

3. JNI native call dài: thread trong trạng thái in_native không thể bị stop tới khi return về Java.

6. Pitfall 1 — counted loop JIT remove back-edge poll

Đây là nguyên nhân phổ biến nhất gây TTSP spike trong production Java.

// Counted loop - int bound
// JIT CO THE remove safepoint poll tai back-edge
public long sumArray(int[] data) {
    long total = 0;
    for (int i = 0; i < data.length; i++) {   // counted loop
        total += data[i];
    }
    return total;
}

Với data.length là int (ví dụ 100 triệu), JIT C2 nhận dạng counted loop và optimize aggressively — bao gồm việc loại bỏ safepoint poll tại back-edge. Vòng lặp chạy mà không poll. Nếu GC request safepoint trong lúc thread đang chạy loop này: TTSP = thời gian chạy hết phần còn lại của loop.

Workaround cổ điển (Java 8-10): dùng long bound thay int để JIT không nhận ra counted loop:

// long bound -> JIT khong consider "counted loop" theo nghia co the remove poll
public long sumArraySafe(long[] data) {
    long total = 0;
    for (long i = 0; i < data.length; i++) {   // not a classic counted loop
        total += data[i];
    }
    return total;
}

Java 10+ cải thiện: JIT thêm safepoint poll lại vào counted loop dài. Tuy nhiên, cách tốt nhất vẫn là đo và diagnose thay vì assume.

Java 16+: JVM thêm flag -XX:+UseCountedLoopSafepoints (enable by default từ Java 16) — buộc JIT giữ safepoint poll trong counted loop. Overhead nhỏ (~1-5%) nhưng TTSP giảm đáng kể.

# Java 16+: da mac dinh bat
# Java 8-15: phai bat thu cong
java -XX:+UseCountedLoopSafepoints MyApp

7. Pitfall 2 — JNI native call block safepoint

Thread gọi JNI native method chuyển sang trạng thái in_native. JVM không thể force-stop thread đang trong native code — native code không có safepoint poll.

JVM phải chờ thread return về Java, lúc đó safepoint poll tại native return boundary mới được check.

// Neu native method chay 500ms, TTSP co the tang len 500ms
public native void nativeLongRunning(byte[] data, int length);

public void process(byte[] largeFile) {
    nativeLongRunning(largeFile, largeFile.length);
    // Thread block trong JNI 500ms
    // GC phai cho 500ms truoc khi safepoint complete
}

Workaround trong native code: code JNI nên tự đặt safepoint check thủ công trong long-running loop:

// JNI C code - manual safepoint check moi N iteration
JNIEXPORT void JNICALL Java_Foo_nativeLongRunning(JNIEnv* env, ...) {
    for (long i = 0; i < count; i++) {
        // ... work ...
        if (i % 10000 == 0) {
            // Cho phep JVM check safepoint - attach/detach pattern
            // Hoac dung VM Thread: (*env)->DetachCurrentThread(vm) roi AttachCurrentThread
        }
    }
}

Trong practice: document rõ native method chạy dài, đặt timeout, hoặc chia nhỏ batch để native call không block quá lâu.

8. Pitfall 3 — String.indexOf trên String rất dài gây TTSP spike

Trong Java 8 và một số Java 11 patch cũ, String.indexOf(String) trên String hàng trăm MB (ví dụ parse log file lớn) có thể chạy hàng chục ms mà không có safepoint poll. JVM dùng native intrinsic (vectorized SIMD instruction) cho indexOf — intrinsic không có safepoint poll.

// TTSP spike: indexOf tren string 100MB
String logContent = readEntireLogFile();   // 100 MB
int pos = logContent.indexOf("ERROR");    // co the 50ms khong safepoint
// GC phai cho 50ms TTSP

Modern JDK (Java 17+) fix bằng cách thêm bounded chunks vào intrinsic — mỗi chunk kiểm tra safepoint. Nếu dùng Java 11 cũ mà gặp TTSP spike, xét dùng BufferedReader để xử lý từng dòng thay vì indexOf trên toàn file.

9. Diagnose TTSP — công cụ và cách đọc

Cách 1: -Xlog:safepoint*=info (Java 9+)

java -Xlog:safepoint*=info:file=safepoint.log MyApp

Output mẫu:

[10.234s][info][safepoint] Safepoint "GC_Minor", Time since last: 4234567900 ns, Reaching safepoint: 128000000 ns, Cleanup: 1234000 ns, At safepoint: 48234000 ns, Total: 177468000 ns

Trường quan trọng:

• Reaching safepoint: TTSP = 128 ms. Đây là thời gian chờ thread arrive.
• At safepoint: thời gian GC thực sự = 48 ms.
• Total: tổng = 177 ms (user thấy).

Nếu "Reaching safepoint" >> "At safepoint" → TTSP là vấn đề, không phải GC algorithm.

Cách 2: JFR event (production-safe)

java -XX:+FlightRecorder \
     -XX:StartFlightRecording=duration=60s,filename=recording.jfr \
     MyApp

Trong JDK Mission Control: Events → VM Operations → filter "Safepoint Begin" + "Safepoint End". Column "Time To Safepoint" chính là TTSP. Sort descending để tìm spike lớn nhất.

Cách 3: -XX:+PrintSafepointStatistics (legacy, pre-Java 9)

java -XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1 MyApp

Print bảng safepoint statistics sau mỗi N safepoint. Java 9+ dùng unified logging thay.

Pattern chẩn đoán:

TTSP spike lớn (> 50ms):
  -> Tim thread dang chay gi trong khoang thoi gian do (JFR thread sample)
  -> Neu counted loop: check -XX:+UseCountedLoopSafepoints (Java 16+)
  -> Neu JNI: chia nho native call
  -> Neu String.indexOf: upgrade JDK hoac process stream

10. Sơ đồ timeline STW pause

gantt
    title Timeline STW Pause (thuc te user thay)
    dateFormat  X
    axisFormat  %Lms

    section JVM
    GC request safepoint    : milestone, 0, 0
    Wait all threads arrive  : crit, 0, 50
    GC work (STW)           : active, 50, 120
    Resume all threads      : milestone, 120, 120

    section Thread 1
    Running                 : 0, 10
    Suspended at safepoint  : crit, 10, 120
    Resumed                 : 120, 130

    section Thread 2
    Running (counted loop)  : 0, 50
    Suspended               : crit, 50, 120
    Resumed                 : 120, 130

    section GC Log
    Reports pause           : active, 50, 120

GC log chỉ báo 70ms (thời gian GC work). User thực sự mất 120ms (TTSP 50ms + GC 70ms). Thread 2 là "slow thread" — đang chạy counted loop 50ms mà không gặp safepoint poll.

11. Thread-local handshake — JEP 312, tối ưu STW

JEP 312 (Java 10) giới thiệu thread-local handshake: khả năng pause một thread cụ thể mà không cần full global STW.

Trước Java 10: mọi operation cần JVM control đều phải stop tất cả thread → STW.

Sau Java 10: JVM có thể gửi signal đến 1 thread cụ thể, pause thread đó, thực hiện operation, rồi resume — trong khi tất cả thread khác vẫn chạy bình thường.

Operation sử dụng thread-local handshake:

• Sampling thread stack (JFR profiling, JVM TI).
• Biased lock revocation (pause chỉ thread đang hold biased lock).
• Deoptimization (pause chỉ thread đang chạy method được deopt).
• Class unloading (một phần).

ZGC tận dụng thread-local handshake để thực hiện nhiều phase GC mà không cần full STW. ZGC chỉ dùng full STW cho Mark Start và Mark End (~1ms mỗi pha).

# Thread-local handshake bat mac dinh tu Java 10+
# Khong can flag rieng - JVM tu dung khi phu hop

12. Deep Dive

13. Self-check

java -Xlog:safepoint*=info:file=safepoint.log:time MyApp