Медленное приложение, частые зависания JVM с однопроцессорными настройками и Java 12+

24

У нас есть клиентское приложение (с 10+ лет разработки). Его JDK был недавно обновлен с OpenJDK 11 до OpenJDK 14. На однопроцессорных (с отключенной гиперпоточностью) настройках Windows 10 (и на машинах VirtualBox с одним доступным ЦП) приложение запускается довольно медленно по сравнению с Java 11. Кроме того, большую часть времени оно использует 100% ЦП. Мы могли бы также воспроизвести проблему с установкой привязки процессора только к одному CPU ( c:\windows\system32\cmd.exe /C start /affinity 1 ...).

Некоторые измерения с запуском приложения и выполнением запроса с минимальным ручным взаимодействием на моей машине VirtualBox:

  • OpenJDK 11.0.2: 36 секунд
  • OpenJDK 13.0.2: ~ 1,5 минуты
  • OpenJDK 13.0.2 с -XX:-UseBiasedLocking: 46 секунд
  • OpenJDK 13.0.2 с -XX:-ThreadLocalHandshakes: 40 секунд
  • OpenJDK 14: 5-6 минут
  • OpenJDK 14 с -XX:-UseBiasedLocking: 3-3,5 минуты
  • OpenJDK 15 EA Build 20: ~ 4,5 минуты

Только использованный JDK (и упомянутые опции) был изменен. ( -XX:-ThreadLocalHandshakesнедоступно в Java 14.)

Мы попытались записать, что делает JDK 14 -Xlog:all=debug:file=app.txt:uptime,tid,level,tags:filecount=50.

Подсчет строк журнала для каждой секунды кажется довольно плавным с 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

С другой стороны, OpenJDK 14, кажется, имеет интересные периоды тишины:

$ 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

Итак, что происходит между секундами 1-4, 7-10 и 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
...

Вторая пауза чуть позже:

...
[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
...

Затем третий:

...
[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)
...

Следующие две строки кажутся интересными:

[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

Это нормально, что эти рукопожатия заняли 5,5 и 6,8 секунды?

Я испытал такое же замедление (и похожие журналы) с демонстрационным приложением update4j (которое совершенно не связано с нашим приложением), работающим с этой командой:

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

Что я должен искать, чтобы снова ускорить работу нашего приложения на однопроцессорных установках Windows 10? Можно ли это исправить, изменив что-то в нашем приложении или добавив аргументы JVM?

Это ошибка JDK, я должен сообщить об этом?

обновление 2020-04-25:

Насколько я вижу, файлы журналов также содержат журналы GC. Это первые журналы GC:

$ 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)
...

К сожалению, это не похоже на связь, поскольку начинается после третьей паузы.

обновление 2020-04-26:

В OpenJDK 14 приложение использует 100% ЦП на моей (однопроцессорной) машине VirtualBox (работающей на ЦП i7-6600U). Виртуальная машина имеет 3,5 ГБ оперативной памяти. По словам диспетчера задач 40% + является свободным, а активность диска составляет 0% (я думаю, это означает, что нет подкачки). Добавление еще одного ЦП к виртуальной машине (и активация гиперпоточности для физических машин) делает приложение снова достаточно быстрым. Мне просто интересно, был ли это преднамеренный компромисс во время разработки JDK с потерей производительности на (редких) однопроцессорных машинах, чтобы ускорить JVM на многоядерных / гиперпоточных процессорах?

java hang java-14 palacsint
источник
3
Включено ли -Xlog:all=debugведение журнала GC? Это было бы мое первое предположение для любых пауз.
Кичик
Вы пробовали работать с профилировщиком и сравнивать результаты? Я думаю, это было бы естественно.
Аксель
1
также проверьте системные сообщения Windows, попробуйте другую сборку для JDK 14. Если все остальное не удается, обострите как проблему?
Ханна111
1
@ Yan.F: OpenJDK 11 не будет поддерживаться вечно, пора готовить новые выпуски и ошибки. Кроме того, это похоже на ошибку JDK - которая может быть исправлена ​​или нет, но может помочь и другим. Во всяком случае, для меня это в основном любопытство. С другой стороны, я бы хотел сейчас сказать, что сказать нашим клиентам как минимальные системные требования нашего приложения.
Palacsint
1
@ Khanna111: Да, я только что написал это как ответ.
Palacsint

Ответы:

6

Из моего опыта проблемы с производительностью JDK связаны в основном с одним из следующих:

  • JIT Компиляция
  • Конфигурация виртуальной машины (размеры кучи)
  • Алгоритм GC
  • Изменения в JVM / JDK, которые ломают известные хорошо работающие приложения
  • (О, и я забыл упомянуть загрузку класса ...)

Если вы просто используете конфигурацию JVM по умолчанию, начиная с OpenJDK11, возможно, вам следует установить некоторые из наиболее заметных опций на фиксированные значения, такие как GC, размер кучи и т. Д.

Возможно, какой-нибудь графический инструмент анализа поможет отследить вашу проблему. Как Retrace, AppDynamics или FlightRecorder и тому подобное. Они дают больше общего обзора общего состояния кучи, циклов gc, оперативной памяти, потоков, загрузки ЦП и т. Д. В определенный момент времени, чем могут предоставить файлы журнала.

Правильно ли я понимаю, что ваше приложение записывает около 30710 строк в журнал в течение первой секунды работы (под OpenJDK11)? Почему он «только» пишет о 7k строк в OpenJDK14 в первую секунду? Мне кажется, это огромная разница для приложения, которое только что запущено на разных JVM ... Вы уверены, что, например, в журнал не помещено большое количество стековых трасс Exception?
Другие числа иногда даже выше, так что, возможно, замедления связаны с регистрацией исключений? Или даже обмен, если RAM становится мало?
На самом деле, я думаю, что если приложение ничего не записывает в журнал, это является признаком бесперебойной работы без проблем (если только в это время оно полностью не заморожено). То, что происходит со секунд 12-22 (в случае OpenJDK14 здесь), это то, что беспокоит меня больше ... зарегистрированные строки проходят через крышу ... почему ?
И после этого ведение журнала снижается до минимальных значений, примерно 1-2 тыс. Строк ... в чем причина этого ? (ну, может быть, это gc включается в секунду 22 и делает tabula rasa, который разрешает некоторые вещи ...?)

Другое дело может быть ваше утверждение о «однопроцессорных» машинах. Означает ли это также «одно ядро» (ИДК, может, ваше программное обеспечение настроено на устаревшее оборудование или что-то в этом роде)? И виртуальные машины с одним процессором работают на этих машинах? Но я предполагаю, что я ошибаюсь в этих предположениях, так как в настоящее время почти все процессоры являются многоядерными ... но я бы мог заняться проблемой многопоточности (взаимоблокировки), возможно.

Antares
источник
2
Пожалуйста, не используйте подписи или слоганы в своих сообщениях, повторяющиеся слова "GL and HF" считаются шумом и отвлекают внимание от содержания вашего сообщения здесь. См. Meta.stackexchange.com/help/behavior для получения дополнительной информации.
Meagar
1
«Правильно ли я понимаю, что ваше приложение записывает в журнал около 30710 строк в течение первой секунды работы (в OpenJDK11)?» - Да, ты прав.
Palacsint
1
«Вы уверены, что, например, в журнал не помещено большое количество стековых трасс Exception?» - Журнал чистый, ничего странного там не нашел, приложение работает правильно (за исключением того, что оно работает очень-очень медленно).
Palacsint
1
GC пинается на 22-й секунде, и приложение остается медленным после этого. Я также обновил вопрос. Обратите внимание, что демо-версия update4j также имеет ту же проблему. Спасибо за ответ!
Palacsint
1
30 тыс. + Логов в секунду - это очень много ... ты не согласен? Мне действительно интересно, что может быть полезно для регистрации, чтобы принять такое большое количество строк журнала за такое короткое время ... Вы пытались полностью отключить регистрацию и профилировать приложение в этом режиме? (Мне любопытно, но, возможно, регистрация действительно не имеет никакого влияния, как вы подразумеваете под поведением update4j)
Antares
5

Поскольку в большинстве случаев он использует 100% ЦП, а в Java 14 это занимает в 10 раз больше времени (!), Это означает, что в Java 14 вы тратите 90% своего ЦП.

Это может привести к нехватке места в куче , поскольку вы проводите много времени в GC, но, похоже, вы это исключили.

Я заметил, что вы настраиваете смещенную блокировку, и она имеет существенное значение. Это говорит мне о том, что, возможно, ваша программа выполняет много параллельной работы в нескольких потоках. Возможно, в вашей программе есть ошибка параллелизма, которая появляется в Java 14, но не в Java 10. Это также может объяснить, почему добавление другого CPU делает его более чем в два раза быстрее.

Ошибки параллелизма часто появляются только тогда, когда вам не повезло, и триггером действительно могло быть что угодно, например, изменение организации hashmap и т. Д.

Во-первых, если это возможно, проверьте наличие петель, которые могут быть заняты, а не спать.

Затем запустите профилировщик в режиме выборки (jvisualvm сделает) и найдите методы, которые занимают гораздо больший% общего времени, чем следовало бы. Поскольку ваша производительность снижается в 10 раз, любые проблемы там действительно должны выпадать.

Мэтт Тиммерманс
источник
Предвзятая блокировка была необходима в прошлом, но сейчас не так сильно, и предлагается отключить ее по умолчанию, а затем удалить: openjdk.java.net/jeps/374
JohannesB
3

TL; DR : это регрессия OpenJDK.

Я не сделал ничего, кроме этого, но я мог воспроизвести проблему с простым привет миром:

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

Я использовал эти два командных файла:

main-1cpu.bat, который ограничивает javaпроцесс только одним процессором:

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, То javaпроцесс может использовать оба 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

(Различия заключаются в affinityзначении и имени файла журнала. Я обернул его для облегчения чтения, но, \вероятно, в Windows это не работает.)

Несколько измерений на Windows 10 x64 в VirtualBox (с двумя процессорами):

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
...

Полученные следы содержат похожие паузы, которые вы можете увидеть в вопросе.

Работа Mainбез трассировки ведется быстрее, но все же можно увидеть разницу между версией с одним и двумя процессорами: ~ 4-7 секунд против ~ 400 мс.

Я отправил эти результаты в список рассылки hotspot-dev @ openjdk, и разработчики подтвердили, что JDK справится с этим лучше . Вы также можете найти предполагаемые исправления в теме. Надеюсь, это будет исправлено в OpenJDK 15.

palacsint
источник
2

Это интересный вопрос, и для его сужения потребуются неопределенные усилия, так как существует множество перестановок и комбинаций, которые необходимо опробовать, а также собрать и сопоставить данные.

Кажется, что в течение некоторого времени не было никакого решения. Возможно, это должно быть обострено.

РЕДАКТИРОВАТЬ 2: Поскольку «ThreadLocalHandshakes» устарела, и мы можем предположить, что блокировка считается допустимой, предложите попробовать без «UseBiasedLocking», чтобы, надеюсь, ускорить этот сценарий.

Однако есть некоторые предложения, чтобы собрать больше данных и попытаться изолировать проблему.

  1. Выделите более одного ядра [Я вижу, что вы попробовали это, и проблема исчезла. Кажется, проблема с выполнением потока / ов, исключающая другие. См № 7 ниже)
  2. Выделите больше кучи (возможно, требования v14 больше, чем у более ранних jdks)
  3. Выделите больше памяти для Win 10 VB.
  4. Проверьте системные сообщения ОС (Win 10 в вашем случае)
  5. Запустите его в не виртуализированной Win 10.
  6. Попробуйте другую сборку JDK 14
  7. Делайте поток дамп каждые (или профиль) несколько интервалов времени. Проанализируйте, какой поток работает исключительно. Возможно, есть настройка для справедливого распределения времени. Возможно, запущен поток с более высоким приоритетом. Что это за нить и что она делает? В Linux вы можете в реальном времени отслеживать легкие процессы (потоки), связанные с процессом и его состоянием. Что-то похожее на Win 10?
  8. Использование процессора? 100% или меньше? Ограничен CPU или mem? 100% CPU в служебных потоках? Какой поток услуг?
  9. Вы явно установили алгоритм GC?

Я лично был свидетелем проблем в версиях, связанных с GC, изменением размера кучи, проблемами с виртуализированными контейнерами и так далее.

Я думаю, что нет простого ответа на этот вопрос, тем более что этот вопрос существует уже некоторое время. Но мы можем попробовать все возможное и дать нам знать, что является результатом некоторых из этих шагов изоляции.

РЕДАКТИРОВАТЬ 1: из обновленного вопроса, это, кажется, связано с GC или другим потоком службы, принимая на себя одно ядро ​​неравномерно (Thread-Local Handshakes)?

Khanna111
источник
Добавление дополнительного ядра ЦП, используемого для запуска перехода с эргономики Java на 32-разрядных системах с клиента на серверный класс vm с различными GC и многоуровневой компиляцией, если это все еще имеет место, это может объяснить внезапные различия в производительности и использовании памяти, да, JVM представление сложное 😁
JohannesB
3
Эргономика Java (настройки по умолчанию) все еще различна для 1 ЦП (например, -XX: + UseSerialGC) или 2 ЦП (например: G1GC, LoopStripMiningIter = 1000, ... ShortLoop = 100) Но после проверки с помощью -XX: + PrintFlagsFinal, что я настроил все параметры на один и тот же или аналогичный запущенный update4j, все еще был чрезвычайно медленным, чтобы начать с одного процессора вместо двух с cmd.exe / C start / affinity 0x1 (но очень быстро с 0x3 - таким образом, используя 2 процессора (1 + 10 бинарных)). Я подтвердил, что мы не можем винить сборщика мусора, используя Epsilon GC, который разработан, чтобы избежать каких-либо накладных расходов GC. TieredCompilation, однако, включен
JohannesB
Понимаю. С Epsilon GC кажется, что это было так же медленно. В этом случае, состояния потока и дампы, чтобы оценить, где он застрял, могли бы быть способом. И в мире Java, и в мире ОС (Linux, если я помню, был gcore)
Khanna111
1

Будьте осторожны с регистрацией на медленных дисках, это замедлит ваше приложение:

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

Но вряд ли это является причиной проблемы, так как процессор все еще занят, и вам не нужно ждать, пока все потоки достигнут безопасной точки, благодаря локальному рукопожатию: https: // openjdk. java.net/jeps/312

Также не имеет прямого отношения к вашей проблеме, но в более общем плане, если вы хотите попытаться увеличить производительность вашего оборудования во время запуска, взгляните на AppCDS (класс обмена данными):

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

JohannesB
источник