Utas Java yang menjalankan operasi sisa dalam satu loop memblokir semua utas lainnya

Cuplikan kode berikut mengeksekusi dua utas, satu pengatur waktu sederhana yang mencatat setiap detik, yang kedua adalah loop tak terbatas yang menjalankan operasi sisa:

public class TestBlockingThread {
    private static final Logger LOGGER = LoggerFactory.getLogger(TestBlockingThread.class);

    public static final void main(String[] args) throws InterruptedException {
        Runnable task = () -> {
            int i = 0;
            while (true) {
                i++;
                if (i != 0) {
                    boolean b = 1 % i == 0;
                }
            }
        };

        new Thread(new LogTimer()).start();
        Thread.sleep(2000);
        new Thread(task).start();
    }

    public static class LogTimer implements Runnable {
        @Override
        public void run() {
            while (true) {
                long start = System.currentTimeMillis();
                try {
                    Thread.sleep(1000);
                } catch (InterruptedException e) {
                    // do nothing
                }
                LOGGER.info("timeElapsed={}", System.currentTimeMillis() - start);
            }
        }
    }
}

Ini memberikan hasil sebagai berikut:

[Thread-0] INFO  c.m.c.concurrent.TestBlockingThread - timeElapsed=1004
[Thread-0] INFO  c.m.c.concurrent.TestBlockingThread - timeElapsed=1003
[Thread-0] INFO  c.m.c.concurrent.TestBlockingThread - timeElapsed=13331
[Thread-0] INFO  c.m.c.concurrent.TestBlockingThread - timeElapsed=1006
[Thread-0] INFO  c.m.c.concurrent.TestBlockingThread - timeElapsed=1003
[Thread-0] INFO  c.m.c.concurrent.TestBlockingThread - timeElapsed=1004
[Thread-0] INFO  c.m.c.concurrent.TestBlockingThread - timeElapsed=1004

Saya tidak mengerti mengapa tugas tak terbatas memblokir semua utas lainnya selama 13,3 detik. Saya mencoba mengubah prioritas utas dan pengaturan lainnya, tidak ada yang berhasil.

Jika Anda memiliki saran untuk memperbaikinya (termasuk menyesuaikan pengaturan pengalihan konteks OS), beri tahu saya.

Setelah semua penjelasan di sini (terima kasih kepada Peter Lawrey ) kami menemukan bahwa sumber utama dari jeda ini adalah bahwa titik aman di dalam loop cukup jarang dicapai sehingga membutuhkan waktu lama untuk menghentikan semua utas untuk penggantian kode yang dikompilasi JIT.

Tetapi saya memutuskan untuk melangkah lebih dalam dan menemukan mengapa titik aman jarang dicapai. Saya merasa agak membingungkan mengapa lompatan belakang whileloop tidak "aman" dalam kasus ini.

Jadi saya memanggil -XX:+PrintAssemblydengan segala kemuliaan untuk membantu

-XX:+UnlockDiagnosticVMOptions \
-XX:+TraceClassLoading \
-XX:+DebugNonSafepoints \
-XX:+PrintCompilation \
-XX:+PrintGCDetails \
-XX:+PrintStubCode \
-XX:+PrintAssembly \
-XX:PrintAssemblyOptions=-Mintel

Setelah beberapa penyelidikan saya menemukan bahwa setelah rekompilasi ketiga dari C2compiler lambda membuang polling safepoint di dalam loop sepenuhnya.

MEMPERBARUI

Selama tahap pembuatan profil variabel itidak pernah terlihat sama dengan 0. Itulah mengapa secara C2spekulatif mengoptimalkan cabang ini, sehingga loop diubah menjadi sesuatu seperti

for (int i = OSR_value; i != 0; i++) {
    if (1 % i == 0) {
        uncommon_trap();
    }
}
uncommon_trap();

Perhatikan bahwa perulangan tak terbatas awalnya dibentuk ulang menjadi perulangan hingga reguler dengan penghitung! Karena pengoptimalan JIT untuk menghilangkan jajak pendapat titik aman dalam pengulangan terhitung hingga, tidak ada jajak pendapat titik aman dalam pengulangan ini.

Setelah beberapa waktu, idibungkus kembali 0, dan jebakan yang tidak biasa diambil. Metode ini tidak dioptimalkan dan terus dijalankan di penerjemah. Selama kompilasi ulang dengan pengetahuan baru C2mengenali loop tak terbatas dan menyerahkan kompilasi. Metode lainnya dilakukan oleh penerjemah dengan titik aman yang tepat.

Ada entri blog bagus yang harus dibaca "Titik Aman: Arti, Efek Samping, dan Overhead" oleh Nitsan Wakart yang mencakup titik aman dan masalah khusus ini.

Penghapusan Safepoint dalam loop yang dihitung sangat lama diketahui menjadi masalah. Bug JDK-5014723(terima kasih Vladimir Ivanov ) mengatasi masalah ini.

Solusi tersedia hingga bug akhirnya diperbaiki.

1. Anda dapat mencoba menggunakan -XX:+UseCountedLoopSafepoints(ini akan menyebabkan penalti performa secara keseluruhan dan dapat menyebabkan JVM crash JDK-8161147 ). Setelah menggunakannya, C2kompilator terus menyimpan titik aman di lompatan belakang dan jeda asli menghilang sepenuhnya.

2. Anda dapat secara eksplisit menonaktifkan kompilasi metode bermasalah dengan menggunakan
   -XX:CompileCommand='exclude,binary/class/Name,methodName'

3. Atau Anda dapat menulis ulang kode Anda dengan menambahkan titik aman secara manual. Misalnya Thread.yield()panggilan di akhir siklus atau bahkan berubah int imenjadi long i(terima kasih, Nitsan Wakart ) juga akan memperbaiki jeda.

Singkatnya, loop yang Anda miliki tidak memiliki titik aman di dalamnya kecuali jika i == 0sudah tercapai. Ketika metode ini dikompilasi dan memicu kode untuk diganti, metode ini perlu membawa semua utas ke titik aman, tetapi ini membutuhkan waktu yang sangat lama, mengunci tidak hanya utas yang menjalankan kode tetapi semua utas di JVM.

Saya menambahkan opsi baris perintah berikut.

-XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime -XX:+PrintCompilation

Saya juga memodifikasi kode untuk menggunakan floating point yang tampaknya membutuhkan waktu lebih lama.

boolean b = 1.0 / i == 0;

Dan yang saya lihat di output adalah

timeElapsed=100
Application time: 0.9560686 seconds
  41423  280 %     4       TestBlockingThread::lambda$main$0 @ -2 (27 bytes)   made not entrant
Total time for which application threads were stopped: 40.3971116 seconds, Stopping threads took: 40.3967755 seconds
Application time: 0.0000219 seconds
Total time for which application threads were stopped: 0.0005840 seconds, Stopping threads took: 0.0000383 seconds
  41424  281 %     3       TestBlockingThread::lambda$main$0 @ 2 (27 bytes)
timeElapsed=40473
  41425  282 %     4       TestBlockingThread::lambda$main$0 @ 2 (27 bytes)
  41426  281 %     3       TestBlockingThread::lambda$main$0 @ -2 (27 bytes)   made not entrant
timeElapsed=100

Catatan: untuk kode yang akan diganti, utas harus dihentikan pada titik aman. Namun tampaknya di sini titik aman seperti itu sangat jarang dicapai (mungkin hanya saat i == 0Mengubah tugas ke

Runnable task = () -> {
    for (int i = 1; i != 0 ; i++) {
        boolean b = 1.0 / i == 0;
    }
};

Saya melihat penundaan serupa.

timeElapsed=100
Application time: 0.9587419 seconds
  39044  280 %     4       TestBlockingThread::lambda$main$0 @ -2 (28 bytes)   made not entrant
Total time for which application threads were stopped: 38.0227039 seconds, Stopping threads took: 38.0225761 seconds
Application time: 0.0000087 seconds
Total time for which application threads were stopped: 0.0003102 seconds, Stopping threads took: 0.0000105 seconds
timeElapsed=38100
timeElapsed=100

Menambahkan kode ke loop dengan hati-hati Anda mendapatkan penundaan yang lebih lama.

for (int i = 1; i != 0 ; i++) {
    boolean b = 1.0 / i / i == 0;
}

mendapat

 Total time for which application threads were stopped: 59.6034546 seconds, Stopping threads took: 59.6030773 seconds

Namun, ubah kode untuk menggunakan metode asli yang selalu memiliki titik aman (jika tidak intrinsik)

for (int i = 1; i != 0 ; i++) {
    boolean b = Math.cos(1.0 / i) == 0;
}

cetakan

Total time for which application threads were stopped: 0.0001444 seconds, Stopping threads took: 0.0000615 seconds

Catatan: menambahkan if (Thread.currentThread().isInterrupted()) { ... }ke perulangan menambahkan titik aman.

Catatan: Ini terjadi pada mesin 16 inti sehingga tidak ada kekurangan sumber daya CPU.

Menemukan jawaban mengapa . Mereka disebut titik aman, dan paling dikenal sebagai Stop-The-World yang terjadi karena GC.

Lihat artikel ini: Logging stop-the-world berhenti di JVM

Peristiwa berbeda dapat menyebabkan JVM menjeda semua utas aplikasi. Jeda seperti itu disebut jeda Stop-The-World (STW). Penyebab paling umum untuk memicu jeda STW adalah pengumpulan sampah (contoh di github), tetapi tindakan JIT yang berbeda (contoh), pencabutan kunci bias (contoh), operasi JVMTI tertentu, dan banyak lagi lainnya juga memerlukan aplikasi untuk dihentikan.

Titik di mana utas aplikasi dapat dihentikan dengan aman disebut, kejutan, titik aman . Istilah ini juga sering digunakan untuk menyebut semua jeda STW.

Lebih atau kurang umum bahwa log GC diaktifkan. Namun, ini tidak menangkap informasi tentang semua titik aman. Untuk mendapatkan semuanya, gunakan opsi JVM ini:

-XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime

Jika Anda bertanya-tanya tentang penamaan yang secara eksplisit merujuk ke GC, jangan khawatir - mengaktifkan opsi ini mencatat semua titik aman, bukan hanya jeda pengumpulan sampah. Jika Anda menjalankan contoh berikut (sumber di github) dengan flag yang ditentukan di atas.

Membaca Glosarium Istilah HotSpot , mendefinisikan ini:

safepoint

Titik selama pelaksanaan program di mana semua akar GC diketahui dan semua konten objek heap konsisten. Dari sudut pandang global, semua utas harus memblokir di titik aman sebelum GC dapat berjalan. (Sebagai kasus khusus, utas yang menjalankan kode JNI dapat terus berjalan, karena hanya menggunakan pegangan. Selama titik aman, utas harus memblokir alih-alih memuat konten pegangan.) Dari sudut pandang lokal, titik aman adalah titik yang dibedakan dalam blok kode di mana thread pelaksana dapat memblokir GC.Sebagian besar situs panggilan memenuhi syarat sebagai titik aman.Ada perbedaan yang kuat yang berlaku di setiap titik aman, yang mungkin diabaikan di titik tidak aman. Baik kode Java yang dikompilasi dan kode C / C ++ dioptimalkan di antara titik aman, tetapi lebih sedikit di seluruh titik aman. Kompilator JIT memancarkan peta GC di setiap titik aman. Kode C / C ++ di VM menggunakan konvensi berbasis makro bergaya (misalnya, TRAPS) untuk menandai potensi titik aman.

Berjalan dengan flag yang disebutkan di atas, saya mendapatkan output ini:

Application time: 0.9668750 seconds
Total time for which application threads were stopped: 0.0000747 seconds, Stopping threads took: 0.0000291 seconds
timeElapsed=1015
Application time: 1.0148568 seconds
Total time for which application threads were stopped: 0.0000556 seconds, Stopping threads took: 0.0000168 seconds
timeElapsed=1015
timeElapsed=1014
Application time: 2.0453971 seconds
Total time for which application threads were stopped: 10.7951187 seconds, Stopping threads took: 10.7950774 seconds
timeElapsed=11732
Application time: 1.0149263 seconds
Total time for which application threads were stopped: 0.0000644 seconds, Stopping threads took: 0.0000368 seconds
timeElapsed=1015

Perhatikan peristiwa STW ketiga:
Total waktu berhenti: 10,7951187 detik
Menghentikan thread yang dibutuhkan: 10,7950774 detik

JIT sendiri hampir tidak memakan waktu, tetapi setelah JVM memutuskan untuk melakukan kompilasi JIT, JIT memasuki mode STW, namun karena kode yang akan dikompilasi (loop tak terbatas) tidak memiliki situs panggilan , tidak ada titik aman yang tercapai.

STW berakhir ketika JIT akhirnya menyerah menunggu dan menyimpulkan kode berada dalam loop tak terbatas.

Setelah mengikuti utas komentar dan beberapa pengujian saya sendiri, saya yakin bahwa jeda ini disebabkan oleh kompiler JIT. Mengapa kompiler JIT membutuhkan waktu yang lama berada di luar kemampuan saya untuk melakukan debug.

Namun, karena Anda hanya menanyakan cara mencegahnya, saya punya solusi:

Tarik loop tak terbatas Anda ke metode yang dapat dikecualikan dari kompiler JIT

public class TestBlockingThread {
    private static final Logger LOGGER = Logger.getLogger(TestBlockingThread.class.getName());

    public static final void main(String[] args) throws InterruptedException     {
        Runnable task = () -> {
            infLoop();
        };
        new Thread(new LogTimer()).start();
        Thread.sleep(2000);
        new Thread(task).start();
    }

    private static void infLoop()
    {
        int i = 0;
        while (true) {
            i++;
            if (i != 0) {
                boolean b = 1 % i == 0;
            }
        }
    }

Jalankan program Anda dengan argumen VM ini:

-XX: CompileCommand = exclude, PACKAGE.TestBlockingThread :: infLoop (ganti PACKAGE dengan informasi paket Anda)

Anda harus mendapatkan pesan seperti ini untuk menunjukkan kapan metode tersebut akan dikompilasi JIT:
### Excludes compile: static blocking.TestBlockingThread :: infLoop
Anda mungkin memperhatikan bahwa saya memasukkan kelas ke dalam paket yang disebut pemblokiran