Aplicación lenta, JVM frecuente se bloquea con configuraciones de CPU única y Java 12+

24

Tenemos una aplicación cliente (con más de 10 años de desarrollo). Su JDK se actualizó de OpenJDK 11 a OpenJDK 14 recientemente. En las configuraciones de Windows 10 de CPU única (hiperprocesamiento deshabilitado) (y dentro de las máquinas VirtualBox con una sola CPU disponible), la aplicación se inicia bastante lentamente en comparación con Java 11. Además, utiliza el 100% de la CPU la mayor parte del tiempo. También podríamos reproducir el problema al configurar la afinidad del procesador a una sola CPU ( c:\windows\system32\cmd.exe /C start /affinity 1 ...).

Algunas medidas al iniciar la aplicación y hacer una consulta con mínima interacción manual en mi máquina VirtualBox:

  • OpenJDK 11.0.2: 36 segundos
  • OpenJDK 13.0.2: ~ 1.5 minutos
  • OpenJDK 13.0.2 con -XX:-UseBiasedLocking: 46 segundos
  • OpenJDK 13.0.2 con -XX:-ThreadLocalHandshakes: 40 segundos
  • OpenJDK 14: 5-6 minutos
  • OpenJDK 14 con -XX:-UseBiasedLocking: 3-3,5 minutos
  • OpenJDK 15 EA Build 20: ~ 4,5 minutos

Solo se ha cambiado el JDK usado (y las opciones mencionadas). ( -XX:-ThreadLocalHandshakesno está disponible en Java 14.)

Hemos intentado registrar lo que hace JDK 14 con -Xlog:all=debug:file=app.txt:uptime,tid,level,tags:filecount=50.

Contar las líneas de registro por segundo parece bastante sencillo con 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

Por otro lado, OpenJDK 14 parece tener períodos tranquilos interesantes:

$ 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

Entonces, ¿qué está pasando entre los segundos 1-4, 7-10 y 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
...

La segunda pausa un poco más tarde:

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

Luego el tercero:

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

Las siguientes dos líneas parecen interesantes:

[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

¿Es normal que estos apretones de manos duraran 5.5 y 6.8 segundos?

He experimentado la misma desaceleración (y registros similares) con la aplicación de demostración update4j (que no tiene ninguna relación con nuestra aplicación) que se ejecuta con este comando:

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

¿Qué debo buscar para que nuestra aplicación sea más rápida nuevamente en configuraciones de Windows 10 con una sola CPU? ¿Puedo solucionar esto cambiando algo en nuestra aplicación o agregando argumentos JVM?

¿Es un error de JDK? ¿Debería informarlo?

actualizar 2020-04-25:

Por lo que veo, los archivos de registro también contienen registros de GC. Estos son los primeros registros de 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)
...

Desafortunadamente, no parece estar relacionado, ya que comienza después de la tercera pausa.

actualizar 2020-04-26:

Con OpenJDK 14, la aplicación utiliza 100% de CPU en mi máquina VirtualBox (CPU única) (que se ejecuta en una CPU i7-6600U). La máquina virtual tiene 3,5 GB de RAM. De acuerdo con el Administrador de tareas, 40% + es gratuito y la actividad del disco es 0% (supongo que esto significa que no hay intercambio). Agregar otra CPU a la máquina virtual (y habilitar el hiperprocesamiento para máquinas físicas) hace que la aplicación vuelva a ser lo suficientemente rápida. Solo me preguntaba, ¿fue una compensación intencional durante el desarrollo de JDK perder rendimiento en máquinas (raras) de CPU única para hacer que la JVM sea más rápida en CPU multinúcleo / hiperprocesador?

java hang java-14 palacsint
fuente
3
¿ -Xlog:all=debugActiva el registro de GC? Esa sería mi primera suposición para cualquier pausa.
kichik
¿Intentaste correr con un generador de perfiles y comparar resultados? Creo que eso sería lo natural.
Axel
1
también revise los mensajes del sistema de Windows, intente una compilación diferente para jdk 14. Si todo lo demás falla, ¿escalar como un problema?
Khanna111
1
@ Yan.F: OpenJDK 11 no será compatible para siempre, es hora de preparar los nuevos lanzamientos y errores. Además, parece un error de JDK, que podría corregirse o no, pero también podría ayudar a otros. De todos modos, para mí es principalmente curiosidad. Por otro lado, me gustaría saber qué decirles a nuestros clientes como requisitos mínimos del sistema de nuestra aplicación.
Palacsint
1
@ Khanna111: Sí, lo acabo de escribir como respuesta.
palacsint

Respuestas:

6

Desde mi experiencia, los problemas de rendimiento con JDK están relacionados principalmente con uno de los siguientes:

  • Compilación JIT
  • Configuración de VM (tamaños de almacenamiento dinámico)
  • Algoritmo GC
  • Cambios en JVM / JDK que rompen las aplicaciones conocidas que funcionan bien
  • (Ah, y olvidé mencionar la carga de clases ...)

Si solo usa la configuración JVM predeterminada desde OpenJDK11, tal vez debería establecer algunas de las opciones más destacadas en valores fijos, como GC, tamaño de almacenamiento dinámico, etc.

Tal vez alguna herramienta de análisis gráfico podría ayudar a rastrear su problema. Como Retrace, AppDynamics o FlightRecorder y similares. Estos brindan más información general sobre el estado general del almacenamiento dinámico, los ciclos gc, la RAM, los subprocesos, la carga de la CPU, etc. en un momento dado de lo que podrían proporcionar los archivos de registro.

¿Entiendo correctamente que su aplicación escribe aproximadamente 30710 líneas en el registro dentro del primer segundo de ejecución (en OpenJDK11)? ¿Por qué "solo" escribe alrededor de 7k líneas bajo OpenJDK14 en el primer segundo? Esto parece una gran diferencia para una aplicación que acaba de iniciarse en diferentes JVM para mí ... ¿Está seguro de que no hay, por ejemplo, grandes cantidades de trazas de pila de Excepción vertidas en el registro?
Los otros números son incluso más altos a veces, ¿entonces tal vez las ralentizaciones están relacionadas con el registro de excepciones? ¿O incluso el intercambio, si la RAM se agota?
En realidad, estoy pensando, si una aplicación no escribe nada en el registro, esto es una señal de buen funcionamiento sin problemas (a menos que esté congelado por completo en este momento). Lo que está sucediendo desde los segundos 12-22 (en el caso de OpenJDK14 aquí) es lo que me preocupa más ... las líneas registradas van por las nubes ... ¿por qué ?
Y luego el registro se reduce a valores bajos de aproximadamente 1-2k líneas ... ¿cuál es la razón para eso ? (bueno, tal vez es el gc pateando en el segundo 22 y hace una tabula rasa que resuelve algunas cosas ...?)

Otra cosa puede ser su declaración acerca de las máquinas de "CPU única". ¿Esto implica "núcleo único" también (Idk, tal vez su software está diseñado en hardware heredado o algo así)? ¿Y las máquinas virtuales de "CPU única" se ejecutan en esas máquinas? Pero supongo que estoy equivocado acerca de estos supuestos, ya que casi todas las CPU son multinúcleo hoy en día ... pero quizás investigaría un problema de subprocesamiento múltiple (punto muerto).

Antares
fuente
2
No utilices firmas o lemas en tus publicaciones, el "GL y HF" repetitivo se considera ruido y una distracción del contenido de tu publicación aquí. Consulte meta.stackexchange.com/help/behavior para obtener más información.
Meagar
1
"¿Entiendo correctamente que su aplicación escribe aproximadamente 30710 líneas en el registro dentro del primer segundo de ejecución (bajo OpenJDK11)?" - Sí tienes razón.
Palacsint
1
"¿Está seguro de que no hay, por ejemplo, grandes cantidades de trazas de pila de excepciones vertidas en el registro?" - El registro está limpio, no he encontrado nada extraño allí, la aplicación funciona correctamente (excepto que se ejecuta muy, muy lentamente).
Palacsint
1
GC está funcionando en el segundo 22 y la aplicación sigue siendo lenta después de eso. También he actualizado la pregunta. Tenga en cuenta que la aplicación de demostración update4j también tiene el mismo problema. ¡Gracias por la respuesta!
Palacsint
1
30k + líneas de registro en un segundo es bastante grande ... ¿no estás de acuerdo? Realmente me pregunto qué podría ser útil para iniciar sesión para aceptar esta gran cantidad de líneas de registro en tan poco tiempo ... ¿Intentó desactivar completamente el registro y crear un perfil de la aplicación en este modo? (Tengo curiosidad, pero tal vez el registro realmente no tiene ningún impacto, ya que implica el comportamiento de update4j)
Antares
5

Dado que está utilizando el 100% de la CPU "la mayor parte del tiempo" y tarda 10 veces más (!) Con Java 14, significa que está desperdiciando el 90% de su CPU en Java 14.

Quedarse sin espacio de almacenamiento dinámico puede hacer eso, ya que pasa mucho tiempo en GC, pero parece que lo ha descartado.

Me doy cuenta de que estás ajustando la opción de bloqueo sesgado, y que hace una diferencia significativa. Eso me dice que tal vez su programa hace mucho trabajo concurrente en múltiples hilos. Es posible que su programa tenga un error de concurrencia que aparece en Java 14, pero no en Java 10. Eso también podría explicar por qué agregar otra CPU hace que sea más del doble de rápido.

Los errores de concurrencia a menudo solo aparecen cuando no tienes suerte, y el desencadenante podría haber sido cualquier cosa, como un cambio en la organización de hashmap, etc.

Primero, si es factible, verifique si hay bucles que puedan estar ocupados esperando en lugar de dormir.

Luego, ejecute un generador de perfiles en modo de muestreo (jvisualvm lo hará) y busque métodos que están tomando un porcentaje de tiempo total mucho mayor de lo que deberían. Dado que su rendimiento está apagado por un factor de 10, cualquier problema allí realmente debería saltarse.

Matt Timmermans
fuente
El bloqueo sesgado era necesario en el pasado pero hoy en día no tanto, y se propone desactivarlo de forma predeterminada y luego eliminarlo: openjdk.java.net/jeps/374
JohannesB hace
3

TL; DR : es una regresión de OpenJDK.

No lo hice excepto eso, pero pude reproducir el problema con un simple hola mundo:

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

He usado estos dos archivos por lotes:

main-1cpu.bat, que limita el javaproceso a una sola 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, el javaproceso puede usar ambas 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

(Las diferencias son el affinityvalor y el nombre del archivo de registro. Lo he incluido para facilitar la lectura, pero \probablemente no funcione en Windows).

Algunas medidas en Windows 10 x64 en VirtualBox (con dos 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
...

Los registros de seguimiento producidos contienen pausas similares que puede ver en la pregunta.

La ejecución Mainsin registros de rastreo es más rápida, pero aún se puede ver la diferencia entre la versión de CPU única y la versión de dos CPU: ~ 4-7 segundos frente a ~ 400 ms.

Envié estos hallazgos a la lista de correo hotspot-dev @ openjdk y los desarrolladores confirmaron que esto es algo que el JDK podría manejar mejor . También puedes encontrar supuestos arreglos en el hilo. Con suerte, se solucionará en OpenJDK 15.

palacsint
fuente
2

Este es un tema interesante y requeriría una cantidad indeterminada de esfuerzo para reducirlo, ya que hay muchas permutaciones y combinaciones que deben probarse y recopilarse y recopilarse datos.

Parece que no ha habido una resolución para esto por algún tiempo. Quizás esto deba ser escalado.

EDITAR 2: Dado que "ThreadLocalHandshakes" está en desuso y podemos suponer que se bloquea el bloqueo, sugiera intentar sin "UseBiasedLocking" para acelerar este escenario.

Sin embargo, hay algunas sugerencias para recopilar más datos e intentar aislar el problema.

  1. Asigne más de un núcleo [veo que lo ha intentado y el problema desaparece. Parece ser un problema con la ejecución de un hilo / s que excluye a otros. Ver no 7 a continuación)
  2. Asigne más almacenamiento dinámico (quizás las demandas de v14 son más que las de jdks anteriores)
  3. Asigne más memoria al Win 10 VB.
  4. Verifique los mensajes del sistema operativo (Win 10 en su caso)
  5. Ejecútelo en un Win 10 no virtualizado.
  6. Pruebe una versión diferente de jdk 14
  7. Haga un volcado de subprocesos cada (o perfil) pocos intervalos de tiempo. Analiza qué hilo se ejecuta exclusivamente. Quizás haya un escenario para compartir el tiempo equitativamente. Quizás haya un subproceso de mayor prioridad en ejecución. ¿Qué es ese hilo y qué está haciendo? En Linux, se pueden calcular los procesos ligeros (hilos) asociados con un proceso y su estado en tiempo real. Algo similar en Win 10?
  8. ¿Uso de CPU? 100% o menos? Restringido por CPU o mem? ¿100% CPU en hilos de servicio? ¿Qué hilo de servicio?
  9. ¿Has configurado explícitamente un GC algo?

Personalmente, he presenciado problemas en las versiones que tienen que ver con GC, cambio de tamaño del montón, problemas con contenedores virtualizados, etc.

Creo que no hay una respuesta fácil para eso, especialmente porque esta pregunta ha estado presente por algún tiempo. Pero podemos intentarlo lo mejor posible y hacernos saber cuál es el resultado de algunos de estos pasos de aislamiento.

EDITAR 1: a partir de la pregunta actualizada, ¿parece estar relacionado con un GC u otro hilo de servicio que se hace cargo del núcleo único de manera no equitativa (Thread-Local Handshakes)?

Khanna111
fuente
Agregar un núcleo de CPU adicional utilizado para activar el cambio de la ergonomía de Java en sistemas de 32 bits de un cliente a un servidor de clase vm con GC diferente y compilación escalonada si ese es el caso, puede explicar diferencias repentinas en el rendimiento y el uso de memoria, sí, JVM el rendimiento es complicado 😁
JohannesB
3
La ergonomía de Java (configuración predeterminada) sigue siendo diferente para 1 CPU (por ejemplo: -XX: + UseSerialGC) o 2 CPU (por ejemplo: G1GC, LoopStripMiningIter = 1000, ... ShortLoop = 100) Pero después de asegurarse con -XX: + PrintFlagsFinal que ajusté todos los parámetros a la misma actualización o ejecución similar 4j todavía era extremadamente lento para comenzar con solo una en lugar de 2 CPU con cmd.exe / C start / affinity 0x1 (pero extremadamente rápido con 0x3, por lo tanto, usando 2 cpus (1 + 10 binarios)). Confirmé que no podemos culpar a ningún recolector de basura usando Epsilon GC, que está diseñado para evitar cualquier sobrecarga de GC. Sin embargo, TieredCompilation está habilitado
JohannesB
Veo. Con Epsilon GC, parece que fue tan lento. En este caso, los estados de subprocesos y los volcados para evaluar dónde se atasca podrían ser una forma. Tanto en el mundo de Java como en el mundo del sistema operativo (Linux si recuerdo era gcore)
Khanna111
1

Tenga cuidado al iniciar sesión en discos lentos, ralentizará su aplicación:

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

Pero no parece ser la causa del problema ya que la CPU todavía está ocupada y no tiene que esperar a que todos los hilos lleguen a un punto seguro gracias al protocolo de enlace local de hilos: https: // openjdk. java.net/jeps/312

Además, no está directamente relacionado con el problema que tiene, pero en general, si desea tratar de obtener más rendimiento de su hardware durante el tiempo de inicio, eche un vistazo a AppCDS (uso compartido de datos de clase):

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

JohannesB
fuente