Performance Profiling

Metrik dari chapter sebelumnya menunjukkan gejala: latensi p95 menanjak, throughput mentok. Pertanyaan berikutnya lebih sulit — method mana yang menyerap waktu prosesor? Menebak dari membaca kode saja adalah jalan klasik menuju optimasi di tempat yang salah: loop yang terlihat mencurigakan sering tidak berarti dibanding satu pemanggilan database yang tersembunyi di lapisan bawah. Profiling menyelesaikannya dengan data: merekam kejadian nyata di JVM yang sedang berjalan, lalu menyusun peringkat tempat waktu dibelanjakan. JDK 25 membawa peralatannya sendiri — Java Flight Recorder, jcmd, jfr — tanpa satu pun alat pihak ketiga.

Ukur Dulu, Baru Optimalkan #

Alur kerja profiling selalu tiga langkah: ukur, temukan hotspot (bagian kecil kode yang menyerap mayoritas waktu), perbaiki hotspot itu, lalu ukur ulang. Tanpa langkah pertama, kita mengoptimalkan berdasarkan intuisi — dan intuisi manusia soal performa terkenal sering meleset. Pernyataan “sudah pasti di sini lambatnya” baru boleh dipercaya setelah profiler menunjuk ke baris yang sama.

Dua keluarga profiler bekerja dengan cara berbeda:

Java Flight Recorder (JFR) memakai pendekatan sampling dengan overhead rendah sehingga lazim dinyalakan terus di produksi.

JFR: Perekam Kejadian Bawaan JDK #

JFR merekam event dari JVM — cuplikan stack, siklus GC, event alokasi, kunci yang menunggu — ke berkas rekaman (.jfr) yang dianalisis terpisah. Rekaman bisa dimulai sejak proses menyala lewat flag, atau ditempelkan ke proses yang sudah berjalan lewat jcmd:

java -XX:StartFlightRecording=duration=60s,filename=rekam.jfr -jar toko-fat.jar
jcmd <pid> JFR.start name=profil1 settings=profile duration=120s
jcmd <pid> JFR.dump name=profil1
jfr print --events jdk.CPULoad,jdk.HotSpotMethodCompilation rekam.jfr
jfr summary rekam.jfr

Perintah jfr summary pada berkas rekaman sungguhan mencetak identitas rekaman (versi format, jumlah chunk, waktu mulai, durasi) lalu tabel jenis event dengan jumlah dan ukurannya — peta isi berkas. jfr print menyajikan event mentah per jenis; JDK Mission Control menyusunnya menjadi flame graph dan garis waktu. Analisis tipikal insiden latensi: urutkan jdk.JavaMonitorWait dan jdk.ThreadPark untuk menemukan thread yang menunggu paling lama, lalu telusuri cuplikan stack-nya.

Profiler Mini Berbasis Penghitung #

Bagaimana profiler menyusun peringkat hotspot? Program berikut merakit versi paling sederhana dari keluarga instrumenting: setiap method menambah penghitungnya sendiri, biaya dibobot per panggilan, lalu tabel disusun dari yang termahal:

import java.util.ArrayList;
import java.util.Comparator;
import java.util.List;

/** Profiler mini: penghitung panggilan per method menemukan hotspot beban kerja. */
public class ProfilHotspot {

    /** Satu baris laporan profil: nama method, jumlah panggilan, biaya per panggilan. */
    record BarisProfil(String method, long panggilan, int opPerPanggilan) {}

    /** Penghitung panggilan: peran instrumentasi profiler. */
    static long panggilValidasi;
    static long panggilHitungTotal;
    static long panggilSimpan;

    static void layaniRequest(int jumlahItem) {
        validasi();
        for (int i = 0; i < jumlahItem; i++) {
            hitungTotal(i);
        }
        simpan();
    }

    static void validasi() {
        panggilValidasi++;
    }

    static void hitungTotal(int item) {
        panggilHitungTotal++;
    }

    static void simpan() {
        panggilSimpan++;
    }

    public static void main(String[] args) {
        for (int r = 0; r < 1000; r++) {
            layaniRequest(3); // tiga item per request
        }

        List<BarisProfil> profil = new ArrayList<>(List.of(
                new BarisProfil("layaniRequest", 1000, 7),
                new BarisProfil("validasi", panggilValidasi, 20),
                new BarisProfil("hitungTotal", panggilHitungTotal, 50),
                new BarisProfil("simpan", panggilSimpan, 30)));
        profil.sort(Comparator.comparingLong((BarisProfil b) -> b.panggilan() * b.opPerPanggilan()).reversed());

        long totalOp = profil.stream().mapToLong(b -> b.panggilan() * b.opPerPanggilan()).sum();
        System.out.println("== Profil beban kerja: 1000 request x 3 item ==");
        System.out.printf("%-14s %10s %13s %10s %7s%n",
                "method", "panggilan", "op/panggilan", "total op", "porsi");
        for (BarisProfil b : profil) {
            long op = b.panggilan() * b.opPerPanggilan();
            System.out.printf("%-14s %10d %13d %10d %6.1f%%%n",
                    b.method(), b.panggilan(), b.opPerPanggilan(), op, 100.0 * op / totalOp);
        }
        System.out.printf("%-14s %10d %13s %10d %7s%n",
                "TOTAL", profil.stream().mapToLong(BarisProfil::panggilan).sum(), "-",
                totalOp, "100%");
    }
}

Output yang Dihasilkan:

== Profil beban kerja: 1000 request x 3 item ==
method          panggilan  op/panggilan   total op   porsi
hitungTotal          3000            50     150000   72.5%
simpan               1000            30      30000   14.5%
validasi             1000            20      20000    9.7%
layaniRequest        1000             7       7000    3.4%
TOTAL                6000             -     207000    100%

Mari kita baca profilnya:

1. Beban kerja: layaniRequest(3) dipanggil 1000 kali — model 1000 request dengan tiga item. Penghitung panggilHitungTotal naik tiga kali per request karena hitungTotal dipanggil dalam lingkaran for.
2. opPerPanggilan: bobot biaya per method — analogi “nanodetik per panggilan” pada profiler nyata. Nilai di sini model tetap; profiler sungguhan mengukurnya dari cuplikan waktu.
3. profil.sort(...): peringkat disusun dari panggilan * opPerPanggilan — total biaya, bukan jumlah panggilan. hitungTotal dipanggil 3000 kali — sama banyaknya dengan gabungan ketiga method lain — tetapi menyerap 72,5% beban: inilah hotspot yang harus diperbaiki lebih dulu.
4. Kolom porsi: persentase terhadap totalOp 207.000. Angka-angka kecil seperti 3,4% untuk layaniRequest adalah pelajaran profil tiap lapisan: optimasi di method yang menyerap 3% memberikan hasil maksimal 3%.
5. Implikasi praktisnya: mengalikan 72,5% → bila hitungTotal bisa dibuat dua kali lebih cepat (misal cache per item), total beban turun sekitar 36% — jauh lebih berdampak daripada menghapus seluruh pekerjaan validasi.

Mikrobenchmark dengan JMH #

Mengukur satu method secara terisolasi butuh alat khusus — JMH (Java Microbenchmark Harness) dari OpenJDK. Masalah yang dijawabnya: JIT compiler mengoptimalkan kode panas, mesin virtual menghapus perhitungan yang hasilnya tak dipakai, dan pengukuran System.nanoTime() sekitar loop menipu. JMH menangani pemanasan, iterasi, dan statistiknya:

@BenchmarkMode(Mode.Throughput)
@OutputTimeUnit(TimeUnit.MILLISECONDS)
@State(Scope.Benchmark)
public class BenchmarkHitungTotal {

    @Benchmark
    public long versiLangsung() {
        return HitungTotal.jumlahkan(1000);
    }

    @Benchmark
    public long versiCache() {
        return HitungTotal.jumlahkanCache(1000);
    }
}

Benchmark dijalankan lewat harness JMH (biasanya plugin Maven/Gradle), bukan main biasa — harness mengatur fork proses terpisah agar dua benchmark tidak saling mencemari status JIT.

Profil menunjukkan di mana waktu dibelanjakan; keputusan optimasi tetap milik kita. Topik berikutnya berpindah dari performa ke penghormatan: cara menghentikan aplikasi tanpa memotong pekerjaan yang setengah jalan — graceful shutdown.

Referensi #

• Oracle: Java Flight Recorder Runtime Guide
• Oracle: jcmd Reference untuk JDK 25
• OpenJDK: JMH — Java Microbenchmark Harness

import java.util.ArrayList;
import java.util.Comparator;
import java.util.List;

/** Profiler mini: penghitung panggilan per method menemukan hotspot beban kerja. */
public class ProfilHotspot {

    /** Satu baris laporan profil: nama method, jumlah panggilan, biaya per panggilan. */
    record BarisProfil(String method, long panggilan, int opPerPanggilan) {}

    /** Penghitung panggilan: peran instrumentasi profiler. */
    static long panggilValidasi;
    static long panggilHitungTotal;
    static long panggilSimpan;

    static void layaniRequest(int jumlahItem) {
        validasi();
        for (int i = 0; i < jumlahItem; i++) {
            hitungTotal(i);
        }
        simpan();
    }

    static void validasi() {
        panggilValidasi++;
    }

    static void hitungTotal(int item) {
        panggilHitungTotal++;
    }

    static void simpan() {
        panggilSimpan++;
    }

    public static void main(String[] args) {
        for (int r = 0; r < 1000; r++) {
            layaniRequest(3); // tiga item per request
        }

        List<BarisProfil> profil = new ArrayList<>(List.of(
                new BarisProfil("layaniRequest", 1000, 7),
                new BarisProfil("validasi", panggilValidasi, 20),
                new BarisProfil("hitungTotal", panggilHitungTotal, 50),
                new BarisProfil("simpan", panggilSimpan, 30)));
        profil.sort(Comparator.comparingLong((BarisProfil b) -> b.panggilan() * b.opPerPanggilan()).reversed());

        long totalOp = profil.stream().mapToLong(b -> b.panggilan() * b.opPerPanggilan()).sum();
        System.out.println("== Profil beban kerja: 1000 request x 3 item ==");
        System.out.printf("%-14s %10s %13s %10s %7s%n",
                "method", "panggilan", "op/panggilan", "total op", "porsi");
        for (BarisProfil b : profil) {
            long op = b.panggilan() * b.opPerPanggilan();
            System.out.printf("%-14s %10d %13d %10d %6.1f%%%n",
                    b.method(), b.panggilan(), b.opPerPanggilan(), op, 100.0 * op / totalOp);
        }
        System.out.printf("%-14s %10d %13s %10d %7s%n",
                "TOTAL", profil.stream().mapToLong(BarisProfil::panggilan).sum(), "-",
                totalOp, "100%");
    }
}