parametry JVM ułatwiające debug

Jeśli mamy na produkcji problemy z wyciekami pamięci lub innymi problemami w naszych aplikacjach uruchamianych na JVM to mogą nam się przydać następujące parametry:

-XX:+HeapDumpOnOutOfMemoryError – flaga zrzucająca dump pamięci podczas gdy aplikacja wyłącza się przez OOM
-XX:OnOutOfMemoryError=… – wykonanie operacji podczas gdy aplikacja wyłącza się przez OOM
- na przykład chcemy zrzucić dump wątków to wpisujemy: „-XX:OnOutOfMemoryError=kill -3 %p”
-XX:+UnlockDiagnosticVMOptions -XX:+LogVMOutput -XX:LogFile=… – zrzut parametrów JVM
- np przykład: -XX:+UnlockDiagnosticVMOptions -XX:+LogVMOutput -XX:LogFile=jvm.log

Przykładowy fragment pliku jvm.log bez opcji : -XX:OnOutOfMemoryError=kill -3 %p

<vm_version>
<name>
OpenJDK 64-Bit Server VM
</name>
<release>
11.0.4+11-post-Ubuntu-1ubuntu218.04.3
</release>
<info>
OpenJDK 64-Bit Server VM (11.0.4+11-post-Ubuntu-1ubuntu218.04.3) for linux-amd64 JRE (11.0.4+11-post-Ubuntu-1ubuntu218.04.3), built on Jul 18 2019 18:21:46 by "buildd" with gcc 7.4.0
</info>
</vm_version>
<vm_arguments>
<args>
-Xmx128m -XX:+HeapDumpOnOutOfMemoryError -XX:+UnlockDiagnosticVMOptions -XX:+LogVMOutput -XX:LogFile=jvm.log </args>
<command>
eu.craftsoft.tech.CrashMain
</command>
<launcher>
SUN_STANDARD
</launcher>
<properties>
java.vm.specification.name=Java Virtual Machine Specification
java.vm.version=11.0.4+11-post-Ubuntu-1ubuntu218.04.3
java.vm.name=OpenJDK 64-Bit Server VM
jdk.debug=release
sun.boot.library.path=/usr/lib/jvm/java-11-openjdk-amd64/lib
java.library.path=/usr/java/packages/lib:/usr/lib/x86_64-linux-gnu/jni:/lib/x86_64-linux-gnu:/usr/lib/x86_64-linux-gnu:/usr/lib/jni:/lib:/usr/lib
java.home=/usr/lib/jvm/java-11-openjdk-amd64
java.class.path=target/crash-mem-1.0-SNAPSHOT.jar
jdk.boot.class.path.append=:/usr/share/java/java-atk-wrapper.jar
java.vm.info=mixed mode, aot, sharing
java.vm.specification.vendor=Oracle Corporation
java.vm.specification.version=11
java.vm.vendor=Ubuntu
sun.java.command=eu.craftsoft.tech.CrashMain
sun.java.launcher=SUN_STANDARD
</properties>
</vm_arguments>
<tty>
<writer thread='442'/>
<blob name='MethodHandlesAdapterBlob' size='32000'>
<sect index='1' size='32000' free='31584'/>
</blob>
java.lang.OutOfMemoryError: Java heap space
Dumping heap to java_pid441.hprof ...
Heap dump file created [161610591 bytes in 19,238 secs]
<writer thread='448'/>
<destroy_vm stamp='24,156'/>
<tty_done stamp='24,159'/>
</tty>
<hotspot_log_done stamp='24,159'/>
</hotspot_log>

A teraz fragment logu wraz ze zrzuceniem wątków:

<?xml version='1.0' encoding='UTF-8'?>
<hotspot_log version='160 1' process='467' time_ms='1573361952698'>
<vm_version>
<name>
OpenJDK 64-Bit Server VM
</name>
<release>
11.0.4+11-post-Ubuntu-1ubuntu218.04.3
</release>
<info>
OpenJDK 64-Bit Server VM (11.0.4+11-post-Ubuntu-1ubuntu218.04.3) for linux-amd64 JRE (11.0.4+11-post-Ubuntu-1ubuntu218.04.3), built on Jul 18 2019 18:21:46 by "buildd" with gcc 7.4.0
</info>
</vm_version>
<vm_arguments>
<args>
-Xmx128m -XX:+HeapDumpOnOutOfMemoryError -XX:OnOutOfMemoryError=kill -3 %p -XX:+UnlockDiagnosticVMOptions -XX:+LogVMOutput -XX:LogFile=jvm.log </args>
<command>
eu.craftsoft.tech.CrashMain
</command>
<launcher>
SUN_STANDARD
</launcher>
<properties>
java.vm.specification.name=Java Virtual Machine Specification
java.vm.version=11.0.4+11-post-Ubuntu-1ubuntu218.04.3
java.vm.name=OpenJDK 64-Bit Server VM
jdk.debug=release
sun.boot.library.path=/usr/lib/jvm/java-11-openjdk-amd64/lib
java.library.path=/usr/java/packages/lib:/usr/lib/x86_64-linux-gnu/jni:/lib/x86_64-linux-gnu:/usr/lib/x86_64-linux-gnu:/usr/lib/jni:/lib:/usr/lib
java.home=/usr/lib/jvm/java-11-openjdk-amd64
java.class.path=target/crash-mem-1.0-SNAPSHOT.jar
jdk.boot.class.path.append=:/usr/share/java/java-atk-wrapper.jar
java.vm.info=mixed mode, aot, sharing
java.vm.specification.vendor=Oracle Corporation
java.vm.specification.version=11
java.vm.vendor=Ubuntu
sun.java.command=eu.craftsoft.tech.CrashMain
sun.java.launcher=SUN_STANDARD
</properties>
</vm_arguments>
<tty>
<writer thread='468'/>
<blob name='MethodHandlesAdapterBlob' size='32000'>
<sect index='1' size='32000' free='31584'/>
</blob>
java.lang.OutOfMemoryError: Java heap space
Dumping heap to java_pid467.hprof ...
Heap dump file created [161693067 bytes in 19,905 secs]
<writer thread='474'/>
#
# java.lang.OutOfMemoryError: Java heap space
# -XX:OnOutOfMemoryError="kill -3 %p"
#   Executing /bin/sh -c "kill -3 467"...
2019-11-10 05:59:36
Full thread dump OpenJDK 64-Bit Server VM (11.0.4+11-post-Ubuntu-1ubuntu218.04.3 mixed mode, sharing):

Threads class SMR info:
_java_thread_list=0x00007fc0d8000b20, length=9, elements={
0x00007fc130013800, 0x00007fc1300e3000, 0x00007fc1300e5000, 0x00007fc1300f3000,
0x00007fc1300f5000, 0x00007fc1300f7800, 0x00007fc1300f9800, 0x00007fc130144000,
0x00007fc13014e000
}

"main" #1 prio=5 os_prio=0 cpu=1756,11ms elapsed=23,43s tid=0x00007fc130013800 nid=0x1d4 waiting on condition  [0x00007fc139725000]
   java.lang.Thread.State: RUNNABLE
	at java.lang.ThreadGroup.uncaughtException(java.base@11.0.4/ThreadGroup.java:1057)
	at java.lang.ThreadGroup.uncaughtException(java.base@11.0.4/ThreadGroup.java:1050)
	at java.lang.Thread.dispatchUncaughtException(java.base@11.0.4/Thread.java:2001)

"Reference Handler" #2 daemon prio=10 os_prio=0 cpu=1,99ms elapsed=23,39s tid=0x00007fc1300e3000 nid=0x1db waiting on condition  [0x00007fc118508000]
   java.lang.Thread.State: RUNNABLE
	at java.lang.ref.Reference.waitForReferencePendingList(java.base@11.0.4/Native Method)
	at java.lang.ref.Reference.processPendingReferences(java.base@11.0.4/Reference.java:241)
	at java.lang.ref.Reference$ReferenceHandler.run(java.base@11.0.4/Reference.java:213)

"Finalizer" #3 daemon prio=8 os_prio=0 cpu=2,61ms elapsed=23,39s tid=0x00007fc1300e5000 nid=0x1dc in Object.wait()  [0x00007fc118407000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(java.base@11.0.4/Native Method)
	- waiting on <0x00000000f8060e10> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@11.0.4/ReferenceQueue.java:155)
	- waiting to re-lock in wait() <0x00000000f8060e10> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@11.0.4/ReferenceQueue.java:176)
	at java.lang.ref.Finalizer$FinalizerThread.run(java.base@11.0.4/Finalizer.java:170)

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 cpu=1,96ms elapsed=23,39s tid=0x00007fc1300f3000 nid=0x1dd runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 cpu=367,00ms elapsed=23,39s tid=0x00007fc1300f5000 nid=0x1de waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

"C1 CompilerThread0" #8 daemon prio=9 os_prio=0 cpu=96,46ms elapsed=23,39s tid=0x00007fc1300f7800 nid=0x1df waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

"Sweeper thread" #9 daemon prio=9 os_prio=0 cpu=15,85ms elapsed=23,39s tid=0x00007fc1300f9800 nid=0x1e0 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Service Thread" #10 daemon prio=9 os_prio=0 cpu=0,50ms elapsed=23,33s tid=0x00007fc130144000 nid=0x1e1 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Common-Cleaner" #11 daemon prio=8 os_prio=0 cpu=1,55ms elapsed=23,32s tid=0x00007fc13014e000 nid=0x1e3 in Object.wait()  [0x00007fc1091f7000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(java.base@11.0.4/Native Method)
	- waiting on <0x00000000f8061760> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@11.0.4/ReferenceQueue.java:155)
	- waiting to re-lock in wait() <0x00000000f8061760> (a java.lang.ref.ReferenceQueue$Lock)
	at jdk.internal.ref.CleanerImpl.run(java.base@11.0.4/CleanerImpl.java:148)
	at java.lang.Thread.run(java.base@11.0.4/Thread.java:834)
	at jdk.internal.misc.InnocuousThread.run(java.base@11.0.4/InnocuousThread.java:134)

"VM Thread" os_prio=0 cpu=4312,12ms elapsed=23,44s tid=0x00007fc1300e0000 nid=0x1da runnable  

"GC Thread#0" os_prio=0 cpu=1540,32ms elapsed=23,49s tid=0x00007fc13002a000 nid=0x1d5 runnable  

"GC Thread#1" os_prio=0 cpu=1553,31ms elapsed=22,99s tid=0x00007fc100001000 nid=0x1e6 runnable  

"GC Thread#2" os_prio=0 cpu=1559,13ms elapsed=22,99s tid=0x00007fc100002800 nid=0x1e7 runnable  

"G1 Main Marker" os_prio=0 cpu=9,80ms elapsed=23,50s tid=0x00007fc130032000 nid=0x1d6 runnable  

"G1 Conc#0" os_prio=0 cpu=495,58ms elapsed=23,50s tid=0x00007fc130034000 nid=0x1d7 runnable  

"G1 Conc#1" os_prio=0 cpu=495,51ms elapsed=22,28s tid=0x00007fc10c001000 nid=0x1eb runnable  

"G1 Refine#0" os_prio=0 cpu=14,58ms elapsed=23,50s tid=0x00007fc1300b8800 nid=0x1d8 runnable  

"G1 Refine#1" os_prio=0 cpu=7,87ms elapsed=22,75s tid=0x00007fc104002000 nid=0x1e8 runnable  

"G1 Refine#2" os_prio=0 cpu=6,28ms elapsed=22,75s tid=0x00007fc0c8001000 nid=0x1e9 runnable  

"G1 Refine#3" os_prio=0 cpu=2,92ms elapsed=22,59s tid=0x00007fc0bc001800 nid=0x1ea runnable  

"G1 Refine#4" os_prio=0 cpu=0,78ms elapsed=21,87s tid=0x00007fc0c0001000 nid=0x1ec runnable  

"G1 Young RemSet Sampling" os_prio=0 cpu=1,85ms elapsed=23,51s tid=0x00007fc1300ba800 nid=0x1d9 runnable  
"VM Periodic Task Thread" os_prio=0 cpu=16,40ms elapsed=23,38s tid=0x00007fc130146800 nid=0x1e2 waiting on condition  

JNI global refs: 9, weak refs: 0

<writer thread='477'/>
Heap
 garbage-first heap   total 10240K, used 694K [0x00000000f8000000, 0x0000000100000000)
  region size 1024K, 1 young (1024K), 0 survivors (0K)
 Metaspace       used 628K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 52K, capacity 386K, committed 512K, reserved 1048576K

<writer thread='474'/>
<destroy_vm stamp='23,552'/>
<tty_done stamp='23,557'/>
</tty>
<hotspot_log_done stamp='23,557'/>
</hotspot_log>

Do analizy wątków, czyli pliku jvm.log możemy wykorzystać stronę:

https://fastthread.io/

Do analizy pamięci możemy wykorzystać stronę:

https://heaphero.io/

parametry JVM ułatwiające debug

Related

Jeden komentarz

Dodaj komentarz Anuluj pisanie odpowiedzi