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

У нас есть клиентское приложение (с 10+ годами разработки). Его JDK недавно был обновлен с OpenJDK 11 до OpenJDK 14. В однопроцессорных (гиперпоточность отключена) установках Windows 10 (и внутри машин VirtualBox только с одним доступным ЦП) приложение запускается довольно медленно по сравнению с Java 11. Кроме того, большую часть времени оно использует 100% ЦП. Мы также можем воспроизвести проблему с установкой привязки процессора только к одному процессору (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, сборка 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 freeze java-14
person palacsint    schedule 22.04.2020    source источник
comment
Включает ли -Xlog:all=debug ведение журнала GC? Это было бы моим первым предположением для любых пауз.   -  person kichik    schedule 25.04.2020
comment
Пробовали ли вы запускать профилировщик и сравнивать результаты? Я думаю, что это было бы естественным поступком.   -  person Axel    schedule 25.04.2020
comment
@kichik: Хороший вопрос, спасибо! К сожалению, он включает журналы GC, проверьте обновление.   -  person palacsint    schedule 25.04.2020
comment
Типичная проблема Java, почему вы хотите использовать новую версию в первую очередь? вы не можете рассчитывать на то, что эти языки с поддержкой GC будут поддерживать стабильную производительность.   -  person Yan.F    schedule 26.04.2020
comment
Такой черный ящик. Это особенность вашей среды или вашего приложения. Можете ли вы попробовать свое приложение в неоднопоточной системе или вне виртуальной машины? А как насчет OpenJ9 jdk? Вы пытались создать свое приложение с помощью нового jdk?   -  person matt    schedule 26.04.2020
comment
Может ли быть так, что последняя версия загружает в память больший набор данных и насыщает кучу, что приводит к паузе, требующей полного gc и часто?   -  person Khanna111    schedule 26.04.2020
comment
Оплатите лицензию Java и получите коммерческую поддержку, например, от Oracle, Azul и т. д.   -  person JohannesB    schedule 26.04.2020
comment
чтобы изолировать его, попробуйте изменить алгоритм gc, выделить более одного ядра, выделить больше кучи. Выделите больше памяти для Win 10 VB. Надеюсь, это поможет изолировать его и дать что-то еще, чтобы продолжать.   -  person Khanna111    schedule 26.04.2020
comment
также проверьте системные сообщения Windows, попробуйте другую сборку для jdk 14. Если ничего не помогает, обострить проблему?   -  person Khanna111    schedule 26.04.2020
comment
пытайтесь создавать дамп потока каждые несколько единиц времени и анализируйте его, чтобы увидеть, что происходит. В Linux вы также можете проверить легкие процессы (потоки), связанные с процессом, и их состояния. Что-то подобное на винде?   -  person Khanna111    schedule 26.04.2020
comment
@Axel: Не могли бы вы предложить профилировщик, который мог бы справиться с этой ситуацией? Машина VirtualBox мучительно медленная, когда работает JVM, потребуется много времени, чтобы попробовать их без предварительных знаний. Буду признателен, если у кого-то есть что-то под рукой и они смогут проверить упомянутый update4j с однопроцессорной установкой Windows 10 OpenJDK 14.   -  person palacsint    schedule 26.04.2020
comment
@Yan.F: OpenJDK 11 не будет поддерживаться вечно, пора готовить новые релизы и ошибки. Кроме того, это похоже на ошибку JDK, которая может быть исправлена ​​или нет, но может помочь и другим. Во всяком случае, для меня это в основном любопытство. С другой стороны, я хотел бы сейчас, что сказать нашим клиентам, как минимальные системные требования нашего приложения.   -  person palacsint    schedule 26.04.2020
comment
@matt: хорошо работает с двухпроцессорными машинами VirtualBox. Переход на другого поставщика JDK кажется большой работой для нашей организации, поэтому я предпочитаю этого избегать. Упомянутое демонстрационное приложение update4j также имеет проблему, и, если я прав, оно было построено с помощью JDK 13.0.1.   -  person palacsint    schedule 26.04.2020
comment
@palacsint отчасти причина, по которой я спрашиваю об openj9 jdk, заключается в том, что он отличается. Это может помочь вам сузить проблему. Я бы предложил зарегистрировать проблему/ошибку update4j.   -  person matt    schedule 27.04.2020
comment
@palacsint: вам удалось это выяснить?   -  person Khanna111    schedule 02.05.2020
comment
@Khanna111: Да, я только что написал это как ответ.   -  person palacsint    schedule 03.05.2020

Ответы (5)


arrow_upward
6
arrow_downward

TL;DR: это регрессия OpenJDK, зарегистрированная как JDK-8244340. и исправлено в JDK 15 Build 24 (20.05.2020).

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

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

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 мог бы справиться лучше. Вы можете найти предполагаемые исправления в теме. слишком. Еще одна ветка о регрессии в hotspot-runtime- разработчик@. Проблема JIRA для исправления: JDK-8244340

person palacsint    schedule 02.05.2020

arrow_upward
5
arrow_downward

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

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

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

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

Правильно ли я понимаю, что ваше приложение пишет около 30710 строк в лог за первую секунду работы (под OpenJDK11)? Почему под OpenJDK14 "всего" пишет около 7к строк в первую секунду? Это кажется мне огромной разницей для приложения, которое только что запущено на разных JVM ... Вы уверены, например, что в журнал не занесено большое количество трассировок стека исключений?

Другие цифры иногда даже выше, так что, возможно, замедление связано с регистрацией исключений? Или даже обмен, если ОЗУ становится мало?

Вообще-то я думаю, если приложение ничего не пишет в лог, то это признак бесперебойной работы (если только оно не зависло за это время целиком). То, что происходит с 12-й по 22-ю секунды (в данном случае с OpenJDK14), меня больше беспокоит... количество записанных строк зашкаливает... почему?

И после этого логирование снижается до рекордно низких значений порядка 1-2к строк... с чем это связано это?? (Ну, может быть, это GC срабатывает на 22-й секунде и делает tabula rasa, которая решает некоторые проблемы...?)

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

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

person Antares    schedule 26.04.2020
comment
Пожалуйста, не используйте подписи или слоганы в своих сообщениях, повторяющиеся GL и HF считаются шумом и отвлечением от содержания вашего сообщения здесь. См. meta.stackexchange.com/help/behavior для получения дополнительной информации. - person meagar; 26.04.2020
comment
Ладно, я и сам задумался о чем-то подобном. Я прекращу шум :D Спасибо за уборку! - person Antares; 26.04.2020
comment
Правильно ли я понимаю, что ваше приложение пишет около 30710 строк в лог за первую секунду работы (под OpenJDK11)? - Да, ты прав. - person palacsint; 26.04.2020
comment
Вы уверены, что, например, в журнал не попадает большое количество трассировок стека исключений? - Журнал чистый, ничего странного я там не нашел, приложение работает корректно (разве что очень-очень медленно). - person palacsint; 26.04.2020
comment
GC срабатывает на 22-й секунде, и после этого приложение остается медленным. Я также обновил вопрос. Обратите внимание, что демо-приложение update4j также имеет ту же проблему. Спасибо за ответ! - person palacsint; 26.04.2020
comment
30 тысяч строк лога в секунду — это очень много… вы согласны? Мне действительно интересно, что может быть полезного в том, чтобы быть в журнале, чтобы принимать такое большое количество строк журнала за такое короткое время ... Вы пробовали полностью отключить ведение журнала и профилировать приложение в этом режиме? (Мне любопытно, но, возможно, ведение журнала действительно не влияет, как вы подразумеваете с поведением update4j) - person Antares; 26.04.2020
comment
В настоящее время я согласен с Мэттом Тиммермансом. Кажется, это блокировка или узкое место в ресурсах при обработке нескольких потоков. Кажется, что ОС неправильно планирует или потоки не могут завершиться на одном процессоре (который, как я подозреваю, является одноядерным), потому что они ждут друг друга. Вам следует попробовать инструмент визуального мониторинга JVM. - person Antares; 26.04.2020
comment
Извините, я неправильно понял вопрос. 30 тысяч строк — это журналы отладки OpenJDK. Приложение регистрирует только 100 строк или около того. Измерения в начале вопроса производились с отключенными логами OpenJDK. - person palacsint; 03.05.2020

arrow_upward
4
arrow_downward

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

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

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

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

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

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

person Matt Timmermans    schedule 26.04.2020
comment
Предвзятая блокировка была необходима в прошлом, но в настоящее время ее не так много, и ее предлагается отключить по умолчанию, а затем удалить: openjdk.java.net/jeps/374 - person JohannesB; 02.05.2020

arrow_upward
2
arrow_downward

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

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

РЕДАКТИРОВАТЬ 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% или меньше? Ограничено процессором или памятью? 100% ЦП в служебных потоках? Какая сервисная ветка?
  9. Вы явно установили алгоритм GC?

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

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

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

person Khanna111    schedule 26.04.2020
comment
Добавление дополнительного ядра ЦП, используемого для запуска переключения с эргономики Java в 32-битных системах с клиента на виртуальную машину серверного класса с другим сборщиком мусора и многоуровневой компиляцией, если это все еще так, это может объяснить внезапные различия в производительности и использовании памяти, да JVM исполнение сложное ???? - person JohannesB; 27.04.2020
comment
Эргономика 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, который разработан, чтобы избежать каких-либо накладных расходов на сборщик мусора. Однако TieredCompilation включен - person JohannesB; 27.04.2020
comment
Я понимаю. С Epsilon GC кажется, что он был таким же медленным. В этом случае можно использовать статусы потоков и дампы для оценки того, где они застревают. Как в мире Java, так и в мире ОС (linux, насколько я помню, был gcore) - person Khanna111; 28.04.2020

arrow_upward
1
arrow_downward

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

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/

person JohannesB    schedule 26.04.2020