Aplikasi lambat, JVM sering hang dengan setup CPU tunggal dan Java 12+

24

Kami memiliki aplikasi klien (dengan 10+ tahun pengembangan). JDK-nya ditingkatkan dari OpenJDK 11 menjadi OpenJDK 14 baru-baru ini. Pada pengaturan Windows 10 single-CPU (hyper-threading dinonaktifkan) (dan di dalam mesin VirtualBox dengan hanya satu CPU yang tersedia) aplikasi dimulai dengan sangat lambat dibandingkan dengan Java 11. Selain itu, ia menggunakan CPU 100% hampir sepanjang waktu. Kami juga dapat mereproduksi masalah dengan mengatur afinitas prosesor menjadi hanya satu CPU ( c:\windows\system32\cmd.exe /C start /affinity 1 ...).

Beberapa pengukuran dengan memulai aplikasi dan melakukan kueri dengan interaksi manual minimal di mesin VirtualBox saya:

  • OpenJDK 11.0.2: 36 detik
  • OpenJDK 13.0.2: ~ 1,5 menit
  • OpenJDK 13.0.2 dengan -XX:-UseBiasedLocking: 46 detik
  • OpenJDK 13.0.2 dengan -XX:-ThreadLocalHandshakes: 40 detik
  • OpenJDK 14: 5-6 menit
  • OpenJDK 14 dengan -XX:-UseBiasedLocking: 3-3,5 menit
  • OpenJDK 15 EA Build 20: ~ 4,5 menit

Hanya JDK yang digunakan (dan opsi yang disebutkan) telah diubah. ( -XX:-ThreadLocalHandshakestidak tersedia di Jawa 14.)

Kami telah mencoba mencatat apa yang dilakukan dengan JDK 14 -Xlog:all=debug:file=app.txt:uptime,tid,level,tags:filecount=50.

Menghitung garis log untuk setiap detik tampaknya cukup lancar dengan OpenJDK 11.0.2:

$ cat jdk11-log/app* | grep "^\[" | cut -d. -f 1 | cut -d[ -f 2 | sort | uniq -c | sort -k 2 -n
  30710 0
  44012 1
  55461 2
  55974 3
  27182 4
  41292 5
  43796 6
  51889 7
  54170 8
  58850 9
  51422 10
  44378 11
  41405 12
  53589 13
  41696 14
  29526 15
   2350 16
  50228 17
  62623 18
  42684 19
  45045 20

Di sisi lain, OpenJDK 14 tampaknya memiliki periode tenang yang menarik:

$ cat jdk14-log/app* | grep "^\[" | cut -d. -f 1 | cut -d[ -f 2 | sort | uniq -c | sort -k 2 -n
   7726 0
   1715 5
  10744 6
   4341 11
  42792 12
  45979 13
  38783 14
  17253 21
  34747 22
   1025 28
   2079 33
   2398 39
   3016 44

Jadi, apa yang terjadi antara detik 1-4, 7-10 dan 14-20?

...
[0.350s][7248][debug][class,resolve        ] jdk.internal.ref.CleanerFactory$1 java.lang.Thread CleanerFactory.java:45
[0.350s][7248][debug][class,resolve        ] jdk.internal.ref.CleanerImpl java.lang.Thread CleanerImpl.java:117
[0.350s][7248][info ][biasedlocking        ] Aligned thread 0x000000001727e010 to 0x000000001727e800
[0.350s][7248][info ][os,thread            ] Thread started (tid: 2944, attributes: stacksize: default, flags: CREATE_SUSPENDED STACK_SIZE_PARAM_IS)
[0.350s][6884][info ][os,thread            ] Thread is alive (tid: 6884).
[0.350s][6884][debug][os,thread            ] Thread 6884 stack dimensions: 0x00000000175b0000-0x00000000176b0000 (1024k).
[0.350s][6884][debug][os,thread            ] Thread 6884 stack guard pages activated: 0x00000000175b0000-0x00000000175b4000.
[0.350s][7248][debug][thread,smr           ] tid=7248: Threads::add: new ThreadsList=0x0000000017254500
[0.350s][7248][debug][thread,smr           ] tid=7248: ThreadsSMRSupport::free_list: threads=0x0000000017253d50 is freed.
[0.350s][2944][info ][os,thread            ] Thread is alive (tid: 2944).
[0.350s][2944][debug][os,thread            ] Thread 2944 stack dimensions: 0x00000000177b0000-0x00000000178b0000 (1024k).
[0.350s][2944][debug][os,thread            ] Thread 2944 stack guard pages activated: 0x00000000177b0000-0x00000000177b4000.
[0.351s][2944][debug][class,resolve        ] java.lang.Thread java.lang.Runnable Thread.java:832
[0.351s][2944][debug][class,resolve        ] jdk.internal.ref.CleanerImpl jdk.internal.misc.InnocuousThread CleanerImpl.java:135
[0.351s][2944][debug][class,resolve        ] jdk.internal.ref.CleanerImpl jdk.internal.ref.PhantomCleanable CleanerImpl.java:138
[0.351s][2944][info ][biasedlocking,handshake] JavaThread 0x000000001727e800 handshaking JavaThread 0x000000000286d800 to revoke object 0x00000000c0087f78
[0.351s][2944][debug][vmthread               ] Adding VM operation: HandshakeOneThread
[0.351s][6708][debug][vmthread               ] Evaluating non-safepoint VM operation: HandshakeOneThread
[0.351s][6708][debug][vmoperation            ] begin VM_Operation (0x00000000178af250): HandshakeOneThread, mode: no safepoint, requested by thread 0x000000001727e800

# no log until 5.723s

[5.723s][7248][info ][biasedlocking          ]   Revoked bias of currently-unlocked object
[5.723s][7248][debug][handshake,task         ] Operation: RevokeOneBias for thread 0x000000000286d800, is_vm_thread: false, completed in 94800 ns
[5.723s][7248][debug][class,resolve          ] java.util.zip.ZipFile$CleanableResource java.lang.ref.Cleaner ZipFile.java:715
[5.723s][7248][debug][class,resolve          ] java.lang.ref.Cleaner jdk.internal.ref.CleanerImpl$PhantomCleanableRef Cleaner.java:220
[5.723s][7248][debug][class,resolve          ] java.util.zip.ZipFile$CleanableResource java.util.WeakHashMap ZipFile.java:716
...

Jeda kedua sedikit kemudian:

...
[6.246s][7248][info ][class,load              ] java.awt.Graphics source: jrt:/java.desktop
[6.246s][7248][debug][class,load              ]  klass: 0x0000000100081a00 super: 0x0000000100001080 loader: [loader data: 0x0000000002882bd0 of 'bootstrap'] bytes: 5625 checksum: 0025818f
[6.246s][7248][debug][class,resolve           ] java.awt.Graphics java.lang.Object (super)
[6.246s][7248][info ][class,loader,constraints] updating constraint for name java/awt/Graphics, loader 'bootstrap', by setting class object
[6.246s][7248][debug][jit,compilation         ]   19       4       java.lang.Object::<init> (1 bytes)   made not entrant
[6.246s][7248][debug][vmthread                ] Adding VM operation: HandshakeAllThreads
[6.246s][6708][debug][vmthread                ] Evaluating non-safepoint VM operation: HandshakeAllThreads
[6.246s][6708][debug][vmoperation             ] begin VM_Operation (0x000000000203ddf8): HandshakeAllThreads, mode: no safepoint, requested by thread 0x000000000286d800
[6.246s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026b0800, is_vm_thread: true, completed in 1400 ns
[6.246s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026bb800, is_vm_thread: true, completed in 700 ns
[6.246s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026ef800, is_vm_thread: true, completed in 100 ns
[6.246s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026f0800, is_vm_thread: true, completed in 100 ns
[6.246s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026f1800, is_vm_thread: true, completed in 100 ns
[6.246s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026f4800, is_vm_thread: true, completed in 100 ns
[6.247s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x0000000002768800, is_vm_thread: true, completed in 100 ns
[6.247s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x000000000276e000, is_vm_thread: true, completed in 100 ns
[6.247s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x0000000017268800, is_vm_thread: true, completed in 100 ns
[6.247s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x000000001727e800, is_vm_thread: true, completed in 800 ns

# no log until 11.783s

[11.783s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x000000000286d800, is_vm_thread: true, completed in 6300 ns
[11.783s][6708][info ][handshake               ] Handshake "Deoptimize", Targeted threads: 11, Executed by targeted threads: 0, Total completion time: 5536442500 ns
[11.783s][6708][debug][vmoperation             ] end VM_Operation (0x000000000203ddf8): HandshakeAllThreads, mode: no safepoint, requested by thread 0x000000000286d800
[11.783s][7248][debug][protectiondomain        ] Checking package access
[11.783s][7248][debug][protectiondomain        ] class loader: a 'jdk/internal/loader/ClassLoaders$AppClassLoader'{0x00000000c0058628} protection domain: a 'java/security/ProtectionDomain'{0x00000000c058b948} loading: 'java/awt/Graphics'
[11.783s][7248][debug][protectiondomain        ] granted
[11.783s][7248][debug][class,resolve           ] sun.launcher.LauncherHelper java.awt.Graphics LauncherHelper.java:816 (reflection)
[11.783s][7248][debug][class,resolve           ] jdk.internal.reflect.Reflection [Ljava.lang.reflect.Method; Reflection.java:300
[11.783s][7248][debug][class,preorder          ] java.lang.PublicMethods$MethodList source: C:\Users\example\AppData\Local\example\stable\jdk\lib\modules
...

Lalu yang ketiga:

...
[14.578s][7248][debug][class,preorder          ] java.lang.InheritableThreadLocal source: C:\Users\example\AppData\Local\example\stable\jdk\lib\modules
[14.578s][7248][info ][class,load              ] java.lang.InheritableThreadLocal source: jrt:/java.base
[14.578s][7248][debug][class,load              ]  klass: 0x0000000100124740 super: 0x0000000100021a18 loader: [loader data: 0x0000000002882bd0 of 'bootstrap'] bytes: 1338 checksum: 8013ed55
[14.578s][7248][debug][class,resolve           ] java.lang.InheritableThreadLocal java.lang.ThreadLocal (super)
[14.578s][7248][debug][jit,compilation         ]  699       3       java.lang.ThreadLocal::get (38 bytes)   made not entrant
[14.578s][7248][debug][vmthread                ] Adding VM operation: HandshakeAllThreads
[14.578s][6708][debug][vmthread                ] Evaluating non-safepoint VM operation: HandshakeAllThreads
[14.578s][6708][debug][vmoperation             ] begin VM_Operation (0x000000000203d228): HandshakeAllThreads, mode: no safepoint, requested by thread 0x000000000286d800
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026b0800, is_vm_thread: true, completed in 1600 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026bb800, is_vm_thread: true, completed in 900 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026ef800, is_vm_thread: true, completed in 100 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026f0800, is_vm_thread: true, completed in 100 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026f1800, is_vm_thread: true, completed in 100 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026f4800, is_vm_thread: true, completed in 0 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x0000000002768800, is_vm_thread: true, completed in 0 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x000000000276e000, is_vm_thread: true, completed in 0 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x0000000017268800, is_vm_thread: true, completed in 0 ns
[14.579s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x000000001727e800, is_vm_thread: true, completed in 900 ns

# no log until 21.455s

[21.455s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x000000000286d800, is_vm_thread: true, completed in 12100 ns
[21.455s][6708][info ][handshake               ] Handshake "Deoptimize", Targeted threads: 11, Executed by targeted threads: 0, Total completion time: 6876829000 ns
[21.455s][6708][debug][vmoperation             ] end VM_Operation (0x000000000203d228): HandshakeAllThreads, mode: no safepoint, requested by thread 0x000000000286d800
[21.455s][7248][debug][class,resolve           ] sun.security.jca.Providers java.lang.InheritableThreadLocal Providers.java:39
[21.455s][7248][info ][class,init              ] 1251 Initializing 'java/lang/InheritableThreadLocal'(no method) (0x0000000100124740)
[21.455s][7248][debug][class,resolve           ] java.lang.InheritableThreadLocal java.lang.ThreadLocal InheritableThreadLocal.java:57
[21.456s][7248][debug][class,preorder          ] sun.security.jca.ProviderList source: C:\Users\example\AppData\Local\example\stable\jdk\lib\modules
[21.456s][7248][info ][class,load              ] sun.security.jca.ProviderList source: jrt:/java.base
[21.456s][7248][debug][class,load              ]  klass: 0x00000001001249a8 super: 0x0000000100001080 loader: [loader data: 0x0000000002882bd0 of 'bootstrap'] bytes: 11522 checksum: bdc239d2
[21.456s][7248][debug][class,resolve           ] sun.security.jca.ProviderList java.lang.Object (super)
...

Dua baris berikut ini tampaknya menarik:

[11.783s][6708][info ][handshake               ] Handshake "Deoptimize", Targeted threads: 11, Executed by targeted threads: 0, Total completion time: 5536442500 ns
[21.455s][6708][info ][handshake               ] Handshake "Deoptimize", Targeted threads: 11, Executed by targeted threads: 0, Total completion time: 6876829000 ns

Apakah itu normal bahwa jabat tangan ini memakan waktu 5,5 dan 6,8 detik?

Saya telah mengalami perlambatan yang sama (dan log serupa) dengan aplikasi demo update4j (yang sama sekali tidak terkait dengan aplikasi kami) berjalan dengan perintah ini:

Z:\swing>\jdk-14\bin\java -Xlog:all=debug:file=app.txt:uptime,tid,level,tags:filecount=50 \
    -jar update4j-1.4.5.jar --remote http://docs.update4j.org/demo/setup.xml

Apa yang harus saya cari untuk membuat aplikasi kita lebih cepat lagi pada pengaturan Windows 10 CPU tunggal? Bisakah saya memperbaiki ini dengan mengubah sesuatu di aplikasi kita atau dengan menambahkan argumen JVM?

Apakah itu bug JDK, haruskah saya melaporkannya?

perbarui 2020-04-25:

Sejauh yang saya lihat file-file log juga berisi log GC. Ini adalah log GC pertama:

$ cat app.txt.00 | grep "\[gc"
[0.016s][7248][debug][gc,heap          ] Minimum heap 8388608  Initial heap 60817408  Maximum heap 1073741824
[0.017s][7248][info ][gc,heap,coops    ] Heap address: 0x00000000c0000000, size: 1024 MB, Compressed Oops mode: 32-bit
[0.018s][7248][info ][gc               ] Using Serial
[22.863s][6708][info ][gc,start                ] GC(0) Pause Young (Allocation Failure)
[22.863s][6708][debug][gc,heap                 ] GC(0) Heap before GC invocations=0 (full 0): def new generation   total 17856K, used 15936K [0x00000000c0000000, 0x00000000c1350000, 0x00000000d5550000)
...

Sayangnya itu tampaknya tidak berhubungan karena dimulai setelah jeda ketiga.

perbarui 2020-04-26:

Dengan OpenJDK 14 aplikasi menggunakan 100% CPU di mesin VirtualBox (single-CPU) saya (berjalan pada CPU i7-6600U). Mesin virtual ini memiliki RAM 3,5 GB. Menurut Task Manager, 40% + gratis dan aktivitas disk adalah 0% (saya kira ini berarti tidak ada pertukaran). Menambahkan CPU lain ke mesin virtual (dan mengaktifkan hyper-threading untuk mesin fisik) membuat aplikasi cukup cepat lagi. Saya hanya ingin tahu, apakah ini merupakan trade-off yang disengaja selama pengembangan JDK untuk kehilangan kinerja pada mesin CPU tunggal (jarang) untuk membuat JVM lebih cepat pada CPU multicore / hyper-threading?

java hang java-14 palacsint
sumber
3
Apakah -Xlog:all=debugmenyalakan pencatatan GC? Itu adalah tebakan pertama saya untuk jeda apa pun.
kichik
Apakah Anda mencoba menjalankan dengan profiler dan membandingkan hasilnya? Saya pikir itu akan menjadi hal yang wajar untuk dilakukan.
Axel
1
juga memeriksa pesan sistem windows, coba membangun yang berbeda untuk jdk 14. Jika semuanya gagal, meningkat sebagai masalah?
Khanna111
1
@ Yan.F: OpenJDK 11 tidak akan didukung selamanya, saatnya mempersiapkan rilis dan bug baru. Selain itu, tampaknya bug JDK - yang mungkin diperbaiki atau tidak tetapi dapat membantu orang lain juga. Ngomong-ngomong, bagi saya sebagian besar rasa ingin tahu. Di sisi lain, saya sekarang ingin memberi tahu pelanggan kami sebagai persyaratan sistem minimal aplikasi kami.
palacsint
1
@ Khanna111: Ya, saya baru saja menuliskannya sebagai jawaban.
palacsint

Jawaban:

6

Dari pengalaman saya, masalah kinerja dengan JDK sebagian besar terkait dengan salah satu dari yang berikut:

  • Kompilasi JIT
  • Konfigurasi VM (ukuran tumpukan)
  • Algoritma GC
  • Perubahan pada JVM / JDK yang memecah aplikasi yang dikenal berjalan baik
  • (Oh, dan aku lupa menyebutkan pemuatan kelas ...)

Jika Anda hanya menggunakan konfigurasi JVM default sejak OpenJDK11, mungkin Anda harus mengatur beberapa opsi yang lebih menonjol untuk nilai tetap, seperti GC, ukuran tumpukan, dll.

Mungkin beberapa alat analisis grafis dapat membantu melacak masalah Anda. Seperti Retrace, AppDynamics atau FlightRecorder dan sejenisnya. Ini memberikan lebih banyak ikhtisar tentang keseluruhan kondisi heap, siklus gc, RAM, utas, beban CPU, dan sebagainya pada waktu tertentu daripada yang bisa disediakan oleh file log.

Apakah saya mengerti benar bahwa aplikasi Anda menulis sekitar 30710 baris ke log dalam detik pertama berjalan (di bawah OpenJDK11)? Mengapa "hanya" menulis tentang 7k baris di bawah OpenJDK14 di detik pertama? Ini sepertinya perbedaan besar untuk aplikasi yang baru saja dimulai pada JVM yang berbeda dengan saya ... Apakah Anda yakin tidak ada contoh tinggi jumlah stacktraces Exception yang dibuang ke log?
Angka-angka lain kadang-kadang bahkan lebih tinggi, jadi mungkin perlambatan terkait dengan penebangan pengecualian? Atau bahkan bertukar, apakah RAM hampir habis?
Sebenarnya saya berpikir, jika suatu aplikasi tidak menulis apa pun ke dalam log, ini adalah tanda kelancaran tanpa masalah (kecuali itu dibekukan sepenuhnya saat ini). Apa yang terjadi dari detik 12-22 (dalam kasus OpenJDK14 di sini) adalah apa yang menjadi perhatian saya lebih lanjut ... garis yang ditebang melewati atap ... mengapa ?
Dan setelah itu logging turun ke sepanjang waktu nilai-nilai rendah sekitar 1-2k baris ... apa alasan untuk itu ?? (yah, mungkin gc yang memulai pada 22 detik dan melakukan tabula rasa yang menyelesaikan beberapa hal ...?)

Hal lain mungkin pernyataan Anda tentang mesin "CPU tunggal". Apakah ini menyiratkan "single core" juga (Idk, mungkin perangkat lunak Anda dirancang pada perangkat keras lama atau semacamnya)? Dan VM "CPU tunggal" berjalan di mesin-mesin itu? Tapi saya berasumsi, saya salah tentang asumsi ini, karena hampir semua CPU multicore saat ini ... tapi saya akan menyelidiki masalah multithreading (deadlock) masalah mungkin.

Antares
sumber
2
Tolong jangan gunakan tanda tangan atau tagline di posting Anda, berulang "GL dan HF" dianggap sebagai gangguan dan gangguan dari konten posting Anda di sini. Lihat meta.stackexchange.com/help/behavior untuk informasi lebih lanjut.
meagar
1
"Apakah saya mengerti benar bahwa aplikasi Anda menulis sekitar 30710 baris ke log dalam detik pertama berjalan (di bawah OpenJDK11)?" - Ya kau benar.
palacsint
1
"Apakah Anda yakin tidak ada contohnya, misalnya stackpacks Exception yang tinggi yang dibuang ke log?" - Log bersih, saya belum menemukan sesuatu yang aneh di sana, aplikasi berfungsi dengan benar (kecuali bahwa itu berjalan sangat-sangat lambat).
palacsint
1
GC menendang di detik ke-22 dan aplikasi tetap lambat setelah itu. Saya juga memperbarui pertanyaan. Harap dicatat bahwa aplikasi demo update4j juga memiliki masalah yang sama. Terima kasih atas jawabannya!
palacsint
1
30k + baris log dalam satu detik cukup besar ... bukankah Anda setuju? Saya benar-benar bertanya-tanya apa yang bisa berguna untuk dicatat untuk menerima jumlah tinggi baris log ini dalam waktu yang singkat ... Apakah Anda mencoba mematikan log sepenuhnya dan profil aplikasi dalam mode ini? (Saya ingin tahu, tetapi mungkin logging benar-benar tidak berdampak karena Anda menyiratkan perilaku update4j)
Antares
5

Karena menggunakan 100% CPU "sebagian besar waktu", dan butuh 10 kali lebih lama (!) Dengan Java 14, itu berarti Anda membuang 90% CPU di Java 14.

Kehabisan ruang tumpukan bisa melakukan itu, karena Anda menghabiskan banyak waktu di GC, tetapi Anda tampaknya telah mengesampingkan itu.

Saya perhatikan bahwa Anda mengubah opsi penguncian yang bias, dan itu membuat perbedaan yang signifikan. Itu memberitahu saya bahwa mungkin program Anda melakukan banyak pekerjaan bersamaan di banyak utas. Mungkin saja program Anda memiliki bug konkurensi yang muncul di Java 14, tetapi tidak di Java 10. Itu juga bisa menjelaskan mengapa menambahkan CPU lain membuatnya lebih cepat dua kali lipat.

Bug konkurensi sering hanya muncul ketika Anda tidak beruntung, dan pemicunya benar-benar bisa apa saja, seperti perubahan ke organisasi hashmap, dll.

Pertama, jika memungkinkan, periksa loop yang mungkin sibuk menunggu alih-alih tidur.

Kemudian, jalankan profiler dalam mode sampling (jvisualvm akan lakukan) dan mencari metode yang mengambil% jauh lebih besar dari total waktu daripada yang seharusnya. Karena kinerja Anda tidak aktif dengan faktor 10, masalah apa pun di sana harus benar-benar hilang.

Matt Timmermans
sumber
Biased Locking diperlukan di masa lalu tetapi saat ini tidak begitu banyak, dan diusulkan untuk dinonaktifkan secara default dan kemudian dihapus: openjdk.java.net/jeps/374
JohannesB
3

TL; DR : Ini adalah regresi OpenJDK.

Saya tidak mengecualikan itu tetapi saya bisa mereproduksi masalah dengan dunia halo sederhana:

public class Main {
    public static void main(String[] args) {
        System.out.println("Hello world");
    }
}

Saya telah menggunakan dua file batch ini:

main-1cpu.bat, yang membatasi javaproses hanya pada satu CPU:

c:\windows\system32\cmd.exe /C start /affinity 1 \
    \jdk-14\bin\java \
    -Xlog:all=trace:file=app-1cpu.txt:uptime,tid,level,tags:filecount=50 \
    Main

main-full.bat, javaprosesnya dapat menggunakan kedua CPU:

c:\windows\system32\cmd.exe /C start /affinity FF \
    \jdk-14\bin\java \
    -Xlog:all=trace:file=app-full.txt:uptime,tid,level,tags:filecount=50 \
    Main

(Perbedaannya adalah affinitynilai dan nama file log. Saya sudah membungkusnya agar lebih mudah dibaca tetapi dibungkus dengan\ mungkin tidak bekerja pada Windows.)

Beberapa pengukuran pada Windows 10 x64 di VirtualBox (dengan dua CPU):

PS Z:\main> Measure-Command { .\main-1cpu.bat }

...    
TotalSeconds      : 7.0203455
...


PS Z:\main> Measure-Command { .\main-full.bat }

...
TotalSeconds      : 1.5751352
...


PS Z:\main> Measure-Command { .\main-full.bat }

...
TotalSeconds      : 1.5585384
...


PS Z:\main> Measure-Command { .\main-1cpu.bat }

...
TotalSeconds      : 23.6482685
...

Tracelog yang dihasilkan berisi jeda serupa yang dapat Anda lihat dalam pertanyaan.

Lari Main tanpa tracelogs lebih cepat tetapi perbedaannya masih dapat dilihat antara versi single-CPU dan dua-CPU: ~ 4-7 detik vs ~ 400 ms.

Saya telah mengirim temuan ini ke daftar mail hotspot-dev @ openjdk dan devs di sana mengkonfirmasi bahwa ini adalah sesuatu yang JDK bisa tangani dengan lebih baik . Anda dapat menemukan perbaikan yang seharusnya di utas juga. Semoga ini akan diperbaiki di OpenJDK 15.

palacsint
sumber
2

Ini adalah masalah yang menarik dan akan membutuhkan upaya yang tidak terbatas untuk mempersempitnya karena ada banyak permutasi dan kombinasi yang perlu dicoba dan data dikumpulkan dan disusun.

Sepertinya belum ada resolusi untuk ini selama beberapa waktu. Mungkin ini perlu ditingkatkan.

EDIT 2: Karena "ThreadLocalHandshakes" sudah usang dan kita dapat mengasumsikan bahwa penguncian diperdebatkan, disarankan mencoba tanpa "UseBiasedLocking" untuk mempercepat skenario ini.

Namun ada beberapa saran untuk mengumpulkan lebih banyak data dan berusaha untuk mengisolasi masalah ini.

  1. Alokasikan lebih dari satu inti [Saya melihat bahwa Anda telah mencobanya dan masalahnya hilang. Tampaknya ada masalah dengan eksekusi utas yang menghalangi orang lain. Lihat no 7 di bawah)
  2. Alokasikan lebih banyak heap (mungkin tuntutan v14 lebih dari pada jdks sebelumnya)
  3. Alokasikan lebih banyak memori ke Win 10 VB.
  4. Periksa pesan sistem OS (Menangkan 10 untuk kasus Anda)
  5. Jalankan dalam Win 10 yang tidak tervirtualisasi.
  6. Coba build yang berbeda dari jdk 14
  7. Lakukan utas dump setiap (atau profil) beberapa interval waktu. Analisis apa utas yang berjalan secara eksklusif. Mungkin ada pengaturan untuk pembagian waktu yang adil. Mungkin ada utas prioritas yang lebih tinggi berjalan. Apa utas itu dan apa yang dilakukannya? Di linux Anda bisa membuat stat proses ringan (utas) yang terkait dengan proses dan statusnya secara realtime. Sesuatu yang serupa pada Win 10?
  8. Penggunaan CPU? 100% atau kurang? Dibatasi oleh CPU atau mem? 100% CPU dalam utas layanan? Utas layanan yang mana?
  9. Apakah Anda secara eksplisit mengatur GC algo?

Saya pribadi telah menyaksikan masalah dalam versi yang berkaitan dengan GC, mengubah ukuran, masalah dengan wadah tervirtualisasi dan sebagainya.

Tidak ada jawaban mudah untuk itu, saya pikir, terutama karena pertanyaan ini telah ada selama beberapa waktu. Tetapi kita dapat mencoba, yang terbaik dan memberi tahu kami apa hasil dari beberapa langkah isolasi ini.

EDIT 1: dari pertanyaan yang diperbarui, tampaknya terkait dengan GC atau utas layanan lain yang mengambil alih inti tunggal secara tidak merata (Jabat Tangan Jabatan Lokal)?

Khanna111
sumber
Menambahkan inti CPU tambahan yang digunakan untuk memicu beralih dari ergonomi Java pada sistem 32 bit dari klien ke server kelas vm dengan GC yang berbeda dan Kompilasi Berjenjang jika itu masih terjadi, hal itu dapat menjelaskan perbedaan mendadak dalam kinerja dan penggunaan memori, ya JVM kinerjanya rumit 😁
JohannesB
3
Java ergonomics (pengaturan default) masih berbeda untuk 1 CPU (mis .: -XX: + UseSerialGC) atau 2 CPU (mis: G1GC, LoopStripMiningIter = 1000, ... ShortLoop = 100) Tetapi setelah memastikan dengan -XX: + PrintFlagsFinal yang saya tweak semua parameter untuk menjalankan pembaruan4j yang sama atau serupa masih sangat lambat untuk memulai dengan hanya satu bukan 2 CPU dengan cmd.exe / C start / afinitas 0x1 (tetapi sangat cepat dengan 0x3 - sehingga menggunakan 2 cpus (1 + 10 biner)). Saya mengonfirmasi bahwa kami tidak dapat menyalahkan pengumpul sampah dengan menggunakan Epsilon GC yang dirancang untuk menghindari overhead GC. Namun TieredCompilation diaktifkan
JohannesB
Saya melihat. Dengan Epsilon GC, sepertinya lambat. Dalam hal ini, status utas dan kesedihan untuk mengevaluasi di mana macet bisa menjadi jalan. Baik di dunia Java dan dunia OS (linux jika saya ingat adalah gcore)
Khanna111
1

Berhati-hatilah dengan masuk ke memperlambat disk, ini akan memperlambat aplikasi Anda:

https://engineering.linkedin.com/blog/2016/02/eliminating-large-jvm-gc-pauses-caus-by-background-io-traffic

Tapi sepertinya tidak menjadi penyebab masalah karena CPU masih sibuk dan Anda tidak perlu menunggu semua utas datang ke titik yang aman berkat jabat tangan lokal-utas: https: // openjdk. java.net/jeps/312

Juga tidak terkait langsung dengan masalah yang Anda miliki tetapi lebih umum jika Anda ingin mencoba memeras lebih banyak kinerja dari perangkat keras Anda untuk waktu startup, lihat AppCDS (berbagi data kelas):

https://blog.codefx.org/java/application-class-data-sharing/

JohannesB
sumber