search

eclipse-openj9 / openj9

Eclipse OpenJ9: A Java Virtual Machine for OpenJDK that's optimized for small footprint, fast start-up, and high throughput. Builds on Eclipse OMR (https://github.com/eclipse/omr) and combines with the Extensions for OpenJDK for OpenJ9 repo.
Other
3.28k stars 721 forks source link

The JVM process enters a dead state, the heap memory is exhausted, no report OOM Error, why? #14012

Closed jackin853 closed 1 year ago

jackin853 commented 2 years ago

Java -version output

openjdk version "1.8.0_275" OpenJDK Runtime Environment (build 1.8.0_275-b01) Eclipse OpenJ9 VM (build openj9-0.23.0, JRE 1.8.0 Linux amd64-64-Bit Compressed References 20201110_845 (JIT enabled, AOT enabled) OpenJ9 - 0394ef754 OMR - 582366ae5 JCL - b52d2ff7ee based on jdk8u275-b01)

Summary of problem

The JVM process enters a suspended animation state(dead state), the application cannot provide services, the heap memory is almost exhausted, and a large number of GC threads occupy the CPU. The JavaCore file can only be exported through the kill -3 command. I want to know why the process does not report OOM Error, but keeps In dead state, why doesn't OOM trigger? And no other abnormalities were found through the javacore file, only the heap memory was indeed exhausted, and part of the GC history

Diagnostic files

JAVACORE FILE MEMINFO PART: 2MEMUSER+—JIT: 308,671,312 bytes / 6472 allocations I +—JIT Code Cache: 268,435,456 bytes / 1 allocation I I I +—JIT Data Cache: 10,486,080 bytes / 5 allocations I I I +—Other: 29,749,776 bytes / 6466 allocations I +—Class Libraries: 2,587,000 bytes / 199 allocations I I I +—VM Class Libraries: 2,587,000 bytes / 199 allocations I I I I I +—sun.misc.Unsafe: 2,504,032 bytes / 167 allocations Illi I I I +—Direct Byte Buffers: 950,144 bytes / 129 allocations Illi I I I +—Other: 1,553,888 bytes / 38 allocations I I I I I +—Other: 82,968 bytes / 32 allocations NULL -------------------------------- OSECTION MEMINFO subcomponent dump routine NULL ================================= NULL 1STHEAPTOTAL Total memory: 2254831616 (0x0000000086660000) 1STHEAPINUSE Total memory in use: 2254831616 (0x0000000086660000) 1STHEAPFREE Total memory free: 0 (0x0000000000000000)


JAVACORE FILE GC history PART:
1STGCHTYPE  GC History
3STHSTTYPE  02:54:22:055231000 GMT j9mm.136 - Compact start: reason=compact on aggressive collection
3STHSTTYPE  02:54:22:055229000 GMT j9mm.57 - Sweep end
3STHSTTYPE  02:54:22:036054000 GMT j9mm.56 - Sweep start
3STHSTTYPE  02:54:22:036052000 GMT j9mm.94 - Class unloading end: classloadersunloaded=0 classesunloaded=0
3STHSTTYPE  02:54:22:036020000 GMT j9mm.60 - Class unloading start
3STHSTTYPE  02:54:22:036019000 GMT j9mm.55 - Mark end
3STHSTTYPE  02:54:21:083918000 GMT j9mm.54 - Mark start
3STHSTTYPE  02:54:21:083553000 GMT j9mm.474 - GlobalGC start: globalcount=449555
3STHSTTYPE  02:54:21:082688000 GMT j9mm.135 - Exclusive access: exclusiveaccessms=l.235 meanexclusiveaccessms=l.235 threads=0 lastthreadtid=0x0000000001B0EE80 beatenbyotherthread=0
3STHSTTYPE  02:54:21:082687000 GMT j9mm.469 - Allocation failure cycle start: newspace=0/563609600 oldspace=16912384/1691222016 loa=16912384/16912384 requestedbytes=24
3STHSTTYPE  02:54:21:081913000 GMT j9mm.470 - Allocation failure cycle end: newspace=0/563609600 oldspace=16912384/1691222016 loa=16912384/16912384
3STHSTTYPE  02:54:21:081827000 GMT j9mm.468 - Cycle End: type 2 approximateFreeMemorySize 16912384
3STHSTTYPE  02:54:21:079713000 GMT j9mm.560 - LocalGC end: rememberedsetoverflow=0 causedrememberedsetoverflow=0 scancacheoverflow=0 failedflipcount=l failedflipbytes=40 failedtenurecount=598767 failedtenurebytes=15608320 flipcount=6766908 flipbytes=167440888 newspace=0/563609600 oldspace=16912384/1691222016 loa=l6912384/16912384 tenureage=0
3STHSTTYPE 02:54:21:078660000 GMT j9mm.140 - Tilt ratio: 70
3STHSTTYPE 02:54:20:146693000 GMT j9mm.63 - Set scavenger backout flag=true
3STHSTTYPE 02:54:19:833122000 GMT j9mm.64 - LocalGC start: globalcount=449555 scavengecount=450902 weakrefs=0 soft=0 phantom=0 finalizers=0
3STHSTTYPE 02:54:19:833113000 GMT j9mm.63 - Set scavenger backout flag=false
3STHSTTYPE 02:54:19:833112000 GMT j9mm.467 - Cycle Start: type 2 approximateFreeMemorySize 173423520
3STHSTTYPE 02:54:19:832503000 GMT j9mm.135 - Exclusive access: exclusiveaccessms=l.235 meanexclusiveaccessms=l.235 threads=0 lastthreadtid=0x0000000001B0EE80 beatenbyotherthread=l
3STHSTTYPE 02:54:19:832502000 GMT j9mm.469 - Allocation failure cycle start: newspace=0/563609600 oldspace=173423520/1691222016 loa=16912384/16912384 requestedbytes=24
3STHSTTYPE 02:54:19:832501000 GMT j9mm.133 - Allocation failure start: newspace=0/563609600 oldspace=173423520/1691222016 loa=16912384/16912384 requestedbytes=24
3STHSTTYPE 02:54:19:827621000 GMT j9mm.134 - Allocation failure end: newspace=0/563609600 oldspace=173423520/1691222016 loa=16912384/16912384
3STHSTTYPE 02:54:19:827615000 GMT j9mm.470 - Allocation failure cycle end: newspace=0/563609600 oldspace=173423520/1691222016 loa=16912384/16912384
3STHSTTYPE 02:54:19:823292000 GMT j9mm.475 - GlobalGC end: workstackoverflow=0 overflowcount=0 memory=173423544/2254831616 
3STHSTTYPE 02:54:19:822090000 GMT j9mm.90 - GlobalGC collect complete
3STHSTTYPE 02:54:19:819752000 GMT j9mm.57 - Sweep end
3STHSTTYPE 02:54:19:795694000 GMT j9mm.56 - Sweep start
3STHSTTYPE 02:54:19:795692000 GMT j9mm.94 - Class unloading end: classloadersunloaded=0 classesunloaded=0 
3STHSTTYPE 02:54:19:795653000 GMT j9mm.60 - Class unloading start
3STHSTTYPE 02:54:19:795651000 GMT j9mm.55 - Mark end
3STHSTTYPE 02:54:18:820671000 GMT j9mm.54 - Mark start
3STHSTTYPE 02:54:18:820194000 GMT j9mm.474 - GlobalGC start: globalcount=449554
dmitripivkine commented 2 years ago

Would you please provide full javacore file. Also it might help to generate Verbose GC log too.

From this small fragment it is obvious that application is way out of heap space. Here you can see Local GC (Scavenge) failed to complete and switched to Scavenger Blackout mode with percolation to followed Global GC. And most likely this cycle repeats. In theory situation like this should be handled by detection of Excessive GC (which trigger OOM). Please check it is not disabled by -Xdisableexcessivegc. Also we fixed problem with similar symptoms in the past. Would you please try newer JVM?

jackin853 commented 2 years ago

The -Xdisableexcessivegc parameter is not set, and the default should be -Xenableexcessivegc, so should I upgrade the version? Which version should I upgrade to? Was there a similar problem before? Sorry, the javacore file is too long. In the customer environment, security issues are involved and cannot be exported. I can only manually enter some

jackin853 commented 2 years ago

If we upgrade, is there a corresponding updated version of jdk1.8？Thks

pshipton commented 2 years ago

If you update the OpenJ9 version it's also an update to the OpenJDK version. https://developer.ibm.com/languages/java/semeru-runtimes/downloads i.e. 

openjdk version "1.8.0_312"
IBM Semeru Runtime Open Edition (build 1.8.0_312-b07)
Eclipse OpenJ9 VM (build openj9-0.29.0, JRE 1.8.0 Linux amd64-64-Bit Compressed References 20211022_234 (JIT enabled, AOT enabled)
OpenJ9   - e1e72c497
OMR      - 299b6a2d2
JCL      - 8860d39588 based on jdk8u312-b07)
dmitripivkine commented 2 years ago

FYI IBM Semeru Open Edition is a new way of distribution of OpenJ9 (required by legal reasons). The product is the same

dmitripivkine commented 2 years ago

What about generation and providing VerboseGC log (at least header part and tail of 20-30 last GC cycles) ?

pshipton commented 2 years ago

"required by legal reasons" is a very succinct way of putting it. AdoptOpenJDK stopped doing builds and transferred operations to Eclipse Adoptium, which won't create OpenJ9 builds. IBM picked up doing builds of OpenJ9, still using the AdoptOpenJDK/Adoptium build pipelines. The Open Edition has the same GPLv2+CE license as previous builds from AdoptOpenJDK. There is some information at https://developer.ibm.com/blogs/introducing-the-ibm-semeru-runtimes/

See also https://blog.adoptopenjdk.net/2021/03/transition-to-eclipse-an-update/

jackin853 commented 2 years ago

Is there any tool to generate gc log from javacore file?

dmitripivkine commented 2 years ago

Is there any tool to generate gc log from javacore file?

No. The generation of GC Verbose log should be enabled by command line option -verbose:gc. The output can be redirected to file using -Xverbosegclog

pshipton commented 2 years ago

Is there any tool to generate gc log from javacore file?

You can copy the 1STGCHTYPE GC History section using any text editor.

If the problem is repeatable, you can capture a full verbose gc log by re-running using https://www.eclipse.org/openj9/docs/xverbosegclog/

jackin853 commented 2 years ago

The following is the detailed javacore file, all the way to the GC History part, I omitted the other parts:

0SECTION TITLE subcomponent dump routine NULL =============================== 1TICHARSET UTF-8 1TISIGINFO Dump Event "user" (00004000) received 1TIDATETIME Date: 2021/11/19 at 10:54:22:222 1TINANOTIME System nanotime: 6048118219501962 1TIFILENAME Javacore filename: /opt/javacore.20211119.105422.8.0001.txt 1TIREQFLAGS Request Flags: 0x81 (exclusive+preempt) 1TIPREPSTATE Prep State: 0x100 (trace_disabled) 1TIPREPINFO Exclusive VM access not taken: data may not be consistent across javacore sections NULL ------------------------------------------------------------------------ 0SECTION GPINFO subcomponent dump routine NULL ================================ 2XHOSLEVEL OS Level : Linux 3.10.0-957.27.2.el7.x86_64 2XHCPUS Processors - 3XHCPUARCH Architecture : amd64 3XHNUMCPUS How Many : 80 3XHNUMASUP NUMA support enabled NULL
1XHERROR2 Register dump section only produced for SIGSEGV, SIGILL or SIGFPE. NULL
NULL ------------------------------------------------------------------------ 0SECTION ENVINFO subcomponent dump routine NULL ================================= 1CIJAVAVERSION JRE 1.8.0 Linux amd64-64 (build 1.8.0_275-b01) 1CIVMVERSION 20201110_845 1CIJ9VMTAG openj9-0.23.0 1CIJ9VMVERSION 0394ef754 1CIJITVERSION 0394ef754 1CIOMRVERSION 582366ae5_CMPRSS 1CIJCLVERSION b52d2ff7ee based on jdk8u275-b01 1CIJITMODES JIT enabled, AOT enabled, FSD disabled, HCR enabled 1CIRUNNINGAS Running as a standalone JVM 1CIVMIDLESTATE VM Idle State: ACTIVE 1CICONTINFO Running in container : TRUE 1CICGRPINFO JVM support for cgroups enabled : TRUE 1CISTARTTIME JVM start time: 2021/11/05 at 17:25:10:667 1CISTARTNANO JVM start nanotime: 4861966664465465 1CIPROCESSID Process ID: 8 (0x8) 1CICMDLINE [not available] 1CIJAVAHOMEDIR Java Home Dir: /opt/java/openjdk/jre 1CIJAVADLLDIR Java DLL Dir: /opt/java/openjdk/jre/bin 1CISYSCP Sys Classpath: /opt/java/openjdk/jre/lib/amd64/compressedrefs/jclSC180/vm.jar;/opt/java/openjdk/jre/lib/se-service.jar;/opt/java/openjdk/jre/lib/rt.jar;/opt/java/openjdk/jre/lib/resources.jar;/opt/java/openjdk/jre/lib/jsse.jar;/opt/java/openjdk/jre/lib/charsets.jar;/opt/java/openjdk/jre/lib/jce.jar; 1CIUSERARGS UserArgs: 2CIUSERARG -Xoptionsfile=/opt/java/openjdk/jre/lib/amd64/compressedrefs/options.default 2CIUSERARG -Xlockword:mode=default,noLockword=java/lang/String,noLockword=java/util/MapEntry,noLockword=java/util/HashMap$Entry,noLockword=org/apache/harmony/luni/util/ModifiedMap$Entry,noLockword=java/util/Hashtable$Entry,noLockword=java/lang/invoke/MethodType,noLockword=java/lang/invoke/MethodHandle,noLockword=java/lang/invoke/CollectHandle,noLockword=java/lang/invoke/ConstructorHandle,noLockword=java/lang/invoke/ConvertHandle,noLockword=java/lang/invoke/ArgumentConversionHandle,noLockword=java/lang/invoke/AsTypeHandle,noLockword=java/lang/invoke/ExplicitCastHandle,noLockword=java/lang/invoke/FilterReturnHandle,noLockword=java/lang/invoke/DirectHandle,noLockword=java/lang/invoke/ReceiverBoundHandle,noLockword=java/lang/invoke/DynamicInvokerHandle,noLockword=java/lang/invoke/FieldHandle,noLockword=java/lang/invoke/FieldGetterHandle,noLockword=java/lang/invoke/FieldSetterHandle,noLockword=java/lang/invoke/StaticFieldGetterHandle,noLockword=java/lang/invoke/StaticFieldSetterHandle,noLockword=java/lang/invoke/IndirectHandle,noLockword=java/lang/invoke/InterfaceHandle,noLockword=java/lang/invoke/VirtualHandle,noLockword=java/lang/invoke/PrimitiveHandle,noLockword=java/lang/invoke/InvokeExactHandle,noLockword=java/lang/invoke/InvokeGenericHandle,noLockword=java/lang/invoke/VarargsCollectorHandle,noLockword=java/lang/invoke/ThunkTuple 2CIUSERARG -Xjcl:jclse29 2CIUSERARG -Dcom.ibm.oti.vm.bootstrap.library.path=/opt/java/openjdk/jre/lib/amd64/compressedrefs:/opt/java/openjdk/jre/lib/amd64 2CIUSERARG -Dsun.boot.library.path=/opt/java/openjdk/jre/lib/amd64/compressedrefs:/opt/java/openjdk/jre/lib/amd64 2CIUSERARG -Djava.library.path=/opt/java/openjdk/jre/lib/amd64/compressedrefs:/opt/java/openjdk/jre/lib/amd64:/usr/local/tomcat/native-jni-lib:/usr/lib64:/usr/lib 2CIUSERARG -Djava.home=/opt/java/openjdk/jre 2CIUSERARG -Djava.ext.dirs=/opt/java/openjdk/jre/lib/ext 2CIUSERARG -Duser.dir=/opt 2CIUSERARG -XX:+IgnoreUnrecognizedVMOptions 2CIUSERARG -XX:+IdleTuningGcOnIdle 2CIUSERARG -Xshareclasses:name=openj9_system_scc,cacheDir=/opt/java/.scc,readonly,nonFatal 2CIUSERARG -Xlp:codecache:pagesize=4k,nonpageable 2CIUSERARG -Xlp:objectheap:pagesize=4k,warn,nonpageable 2CIUSERARG -Djava.class.path=. 2CIUSERARG -XX:+ExitOnOutOfMemoryError 2CIUSERARG -XX:+UseContainerSupport 2CIUSERARG -XX:MaxRAMPercentage=70 2CIUSERARG -XX:+CompactStrings 2CIUSERARG -XX:-PortableSharedCache 2CIUSERARG -XX:+IdleTuningGcOnIdle 2CIUSERARG -XX:IdleTuningMinIdleWaitTime=120 2CIUSERARG -Djava.security.egd=file:/dev/./urandom 2CIUSERARG -Djava.class.path=/opt/NetconfCollector.jar 2CIUSERARG -Dsun.java.command=/opt/NetconfCollector.jar /opt/application.properties 2CIUSERARG -Dsun.java.launcher=SUN_STANDARD 2CIUSERARG -Dsun.java.launcher.pid=8 NULL 1CIUSERLIMITS User Limits (in bytes except for NOFILE and NPROC) NULL ------------------------------------------------------------------------ NULL type soft limit hard limit 2CIUSERLIMIT RLIMIT_AS unlimited unlimited 2CIUSERLIMIT RLIMIT_CORE unlimited unlimited 2CIUSERLIMIT RLIMIT_CPU unlimited unlimited 2CIUSERLIMIT RLIMIT_DATA unlimited unlimited 2CIUSERLIMIT RLIMIT_FSIZE unlimited unlimited 2CIUSERLIMIT RLIMIT_LOCKS unlimited unlimited 2CIUSERLIMIT RLIMIT_MEMLOCK 65536 65536 2CIUSERLIMIT RLIMIT_NOFILE 1048576 1048576 2CIUSERLIMIT RLIMIT_NPROC unlimited unlimited 2CIUSERLIMIT RLIMIT_RSS unlimited unlimited 2CIUSERLIMIT RLIMIT_STACK 8388608 unlimited 2CIUSERLIMIT RLIMIT_MSGQUEUE 819200 819200 2CIUSERLIMIT RLIMIT_NICE 0 0 2CIUSERLIMIT RLIMIT_RTPRIO 0 0 2CIUSERLIMIT RLIMIT_SIGPENDING 1286527 1286527 NULL 1CIENVVARS Environment Variables NULL ------------------------------------------------------------------------

NULL
1CISYSINFO System Information NULL ------------------------------------------------------------------------ 2CISYSINFO /proc/sys/kernel/core_pattern = core 2CISYSINFO /proc/sys/kernel/core_uses_pid = 1 NULL
1CICPUINFO CPU Information NULL ------------------------------------------------------------------------ 2CIPHYSCPU Physical CPUs: 80 2CIONLNCPU Online CPUs: 80 2CIBOUNDCPU Bound CPUs: 4 2CIACTIVECPU Active CPUs: 0 2CITARGETCPU Target CPUs: 4 NULL 1CICGRPINFO Cgroup Information NULL ------------------------------------------------------------------------ 2CICGRPINFO subsystem : memory 2CICGRPINFO cgroup name : / 3CICGRPINFO Memory Limit : 3221225472 bytes 3CICGRPINFO Memory + Swap Limit : 3221225472 bytes 3CICGRPINFO Memory Usage : 2865176576 bytes 3CICGRPINFO Memory + Swap Usage : 2866008064 bytes 3CICGRPINFO Memory Max Usage : 2904199168 bytes 3CICGRPINFO Memory + Swap Max Usage : 2904199168 bytes 3CICGRPINFO Memory limit exceeded count : 0 3CICGRPINFO Memory + Swap limit exceeded count : 0 3CICGRPINFO OOM Killer Disabled : 0 3CICGRPINFO Under OOM : 0 2CICGRPINFO subsystem : cpuset 2CICGRPINFO cgroup name : / 3CICGRPINFO CPU exclusive : 0 3CICGRPINFO Mem exclusive : 0 3CICGRPINFO CPUs : 0-79 3CICGRPINFO Mems : 0-1 2CICGRPINFO subsystem : cpu 2CICGRPINFO cgroup name : / 3CICGRPINFO CPU Period : 100000 microseconds 3CICGRPINFO CPU Quota : 400000 microseconds 3CICGRPINFO CPU Shares : 2 3CICGRPINFO Period intervals elapsed count : 11860661 3CICGRPINFO Throttled count : 2922610 3CICGRPINFO Total throttle time : 37355308056322 nanoseconds NULL
NULL ------------------------------------------------------------------------ 0SECTION NATIVEMEMINFO subcomponent dump routine NULL ================================= 0MEMUSER 1MEMUSER JRE: 3,280,452,624 bytes / 43306 allocations 1MEMUSER | 2MEMUSER +--VM: 2,969,194,312 bytes / 36635 allocations 2MEMUSER | | 3MEMUSER | +--Classes: 60,813,912 bytes / 2484 allocations 3MEMUSER | | | 4MEMUSER | | +--Shared Class Cache: 13,631,584 bytes / 2 allocations 3MEMUSER | | | 4MEMUSER | | +--Other: 47,182,328 bytes / 2482 allocations 2MEMUSER | | 3MEMUSER | +--Memory Manager (GC): 2,333,305,544 bytes / 13097 allocations 3MEMUSER | | | 4MEMUSER | | +--Java Heap: 2,254,893,056 bytes / 1 allocation 3MEMUSER | | | 4MEMUSER | | +--Other: 78,412,488 bytes / 13096 allocations 2MEMUSER | | 3MEMUSER | +--Threads: 393,485,984 bytes / 6409 allocations 3MEMUSER | | | 4MEMUSER | | +--Java Stack: 29,697,456 bytes / 1330 allocations 3MEMUSER | | | 4MEMUSER | | +--Native Stack: 355,074,048 bytes / 1331 allocations 3MEMUSER | | | 4MEMUSER | | +--Other: 8,714,480 bytes / 3748 allocations 2MEMUSER | | 3MEMUSER | +--Trace: 12,450,296 bytes / 4324 allocations 2MEMUSER | | 3MEMUSER | +--JVMTI: 17,776 bytes / 13 allocations 2MEMUSER | | 3MEMUSER | +--JNI: 933,112 bytes / 2440 allocations 2MEMUSER | | 3MEMUSER | +--Port Library: 156,697,104 bytes / 80 allocations 3MEMUSER | | | 4MEMUSER | | +--Unused <32bit allocation regions: 156,684,344 bytes / 1 allocation 3MEMUSER | | | 4MEMUSER | | +--Other: 12,760 bytes / 79 allocations 2MEMUSER | | 3MEMUSER | +--Other: 11,490,584 bytes / 7788 allocations 1MEMUSER | 2MEMUSER +--JIT: 308,671,312 bytes / 6472 allocations 2MEMUSER | | 3MEMUSER | +--JIT Code Cache: 268,435,456 bytes / 1 allocation 2MEMUSER | | 3MEMUSER | +--JIT Data Cache: 10,486,080 bytes / 5 allocations 2MEMUSER | | 3MEMUSER | +--Other: 29,749,776 bytes / 6466 allocations 1MEMUSER | 2MEMUSER +--Class Libraries: 2,587,000 bytes / 199 allocations 2MEMUSER | | 3MEMUSER | +--VM Class Libraries: 2,587,000 bytes / 199 allocations 3MEMUSER | | | 4MEMUSER | | +--sun.misc.Unsafe: 2,504,032 bytes / 167 allocations 4MEMUSER | | | | 5MEMUSER | | | +--Direct Byte Buffers: 950,144 bytes / 129 allocations 4MEMUSER | | | | 5MEMUSER | | | +--Other: 1,553,888 bytes / 38 allocations 3MEMUSER | | | 4MEMUSER | | +--Other: 82,968 bytes / 32 allocations NULL
NULL ------------------------------------------------------------------------ 0SECTION MEMINFO subcomponent dump routine NULL ================================= NULL
1STHEAPTYPE Object Memory NULL id start end size space/region 1STHEAPSPACE 0x00007FA7800B6330 -- -- -- Generational 1STHEAPREGION 0x00007FA7800B6B20 0x00000000799A0000 0x00000000DE680000 0x0000000064CE0000 Generational/Tenured Region 1STHEAPREGION 0x00007FA7800B6790 0x00000000DE680000 0x00000000F6010000 0x0000000017990000 Generational/Nursery Region 1STHEAPREGION 0x00007FA7800B6400 0x00000000F6010000 0x0000000100000000 0x0000000009FF0000 Generational/Nursery Region NULL 1STHEAPTOTAL Total memory: 2254831616 (0x0000000086660000) 1STHEAPINUSE Total memory in use: 2254831616 (0x0000000086660000) 1STHEAPFREE Total memory free: 0 (0x0000000000000000) NULL 1STSEGTYPE Internal Memory NULL segment start alloc end type size 1STSEGMENT 0x00007FA764029158 0x00007F9D571D2030 0x00007F9D572D0100 0x00007F9D572D2030 0x00800040 0x0000000000100000 1STSEGMENT 0x00007FA780090448 0x00007F9D5A9AC030 0x00007F9D5AAAB3F0 0x00007F9D5AAAC030 0x00800040 0x0000000000100000 1STSEGMENT 0x00007FA780090060 0x00007F9D5AFC3030 0x00007F9D5B0C2F80 0x00007F9D5B0C3030 0x00800040 0x0000000000100000 1STSEGMENT 0x00007FA764034C08 0x00007FA6D03D4030 0x00007FA6D04D4030 0x00007FA6D04D4030 0x00800040 0x0000000000100000 1STSEGMENT 0x00007FA764034CD0 0x00007FA6EA20F030 0x00007FA6EA30F030 0x00007FA6EA30F030 0x00800040 0x0000000000100000 1STSEGMENT 0x00007FA764035248 0x00007FA6EBEBE030 0x00007FA6EBFBE010 0x00007FA6EBFBE030 0x00800040 0x0000000000100000 1STSEGMENT 0x00007FA764035180 0x00007FA7309B9030 0x00007FA730AB9030 0x00007FA730AB9030 0x00800040 0x0000000000100000 1STSEGMENT 0x00007FA764034D98 0x00007FA732A64030 0x00007FA732B64030 0x00007FA732B64030 0x00800040 0x0000000000100000 1STSEGMENT 0x00007FA764035310 0x00007FA733303030 0x00007FA733403020 0x00007FA733403030 0x00800040 0x0000000000100000 1STSEGMENT 0x00007FA7640350B8 0x00007FA7335CB030 0x00007FA7336CB010 0x00007FA7336CB030 0x00800040 0x0000000000100000 1STSEGMENT 0x00007FA764034FF0 0x00007FA7313E8030 0x00007FA7314E8030 0x00007FA7314E8030 0x00800040 0x0000000000100000 1STSEGMENT 0x00007FA78008FED0 0x00007FA73166F030 0x00007FA73176F010 0x00007FA73176F030 0x00800040 0x0000000000100000 1STSEGMENT 0x00007FA780090380 0x00007FA731D88030 0x00007FA731E88030 0x00007FA731E88030 0x00800040 0x0000000000100000 1STSEGMENT 0x00007FA780090510 0x00007FA76AEED030 0x00007FA76AFED030 0x00007FA76AFED030 0x00800040 0x0000000000100000 1STSEGMENT 0x00007FA764034E60 0x00007FA780DFB5B0 0x00007FA780EFB5B0 0x00007FA780EFB5B0 0x00800040 0x0000000000100000 1STSEGMENT 0x00007FA764034F28 0x00007FA76B0B1030 0x00007FA76B1B1000 0x00007FA76B1B1030 0x00800040 0x0000000000100000 1STSEGMENT 0x00007FA780090128 0x00007FA76B1F3030 0x00007FA76B2F3010 0x00007FA76B2F3030 0x00800040 0x0000000000100000 1STSEGMENT 0x00007FA7800901F0 0x00007FA7327CC030 0x00007FA7328CC030 0x00007FA7328CC030 0x00800040 0x0000000000100000 1STSEGMENT 0x00007FA78008FE08 0x00007FA77C176030 0x00007FA77C276030 0x00007FA77C276030 0x00800040 0x0000000000100000 NULL 1STSEGTOTAL Total memory: 19922944 (0x0000000001300000) 1STSEGINUSE Total memory in use: 19911456 (0x00000000012FD320) 1STSEGFREE Total memory free: 11488 (0x0000000000002CE0) NULL
1STSEGTYPE Class Memory NULL segment start alloc end type size ...................... NULL 1STSEGTOTAL Total memory: 57204000 (0x000000000368DD20) 1STSEGINUSE Total memory in use: 48070168 (0x0000000002DD7E18) 1STSEGFREE Total memory free: 9133832 (0x00000000008B5F08) NULL
1STSEGTYPE JIT Code Cache NULL segment start alloc end type size 1STSEGMENT 0x00007FA780104DA8 0x00007FA76B600000 0x00007FA76C6AEA00 0x00007FA77B600000 0x00000068 0x0000000010000000 NULL 1STSEGTOTAL Total memory: 268435456 (0x0000000010000000) 1STSEGINUSE Total memory in use: 17492480 (0x00000000010AEA00) 1STSEGFREE Total memory free: 250942976 (0x000000000EF51600) 1STSEGLIMIT Allocation limit: 268435456 (0x0000000010000000) NULL
1STSEGTYPE JIT Data Cache NULL segment start alloc end type size 1STSEGMENT 0x00007FA75C027960 0x00007F9D57B75030 0x00007F9D57D75030 0x00007F9D57D75030 0x00000048 0x0000000000200000 1STSEGMENT 0x00007FA75C027898 0x00007FA6D1315030 0x00007FA6D1515030 0x00007FA6D1515030 0x00000048 0x0000000000200000 1STSEGMENT 0x00007FA7801053C8 0x00007FA7336CC030 0x00007FA7338CC030 0x00007FA7338CC030 0x00000048 0x0000000000200000 1STSEGMENT 0x00007FA780105300 0x00007FA76A8DC030 0x00007FA76AADC030 0x00007FA76AADC030 0x00000048 0x0000000000200000 1STSEGMENT 0x00007FA780105238 0x00007FA7692D4030 0x00007FA7694D4030 0x00007FA7694D4030 0x00000048 0x0000000000200000 NULL 1STSEGTOTAL Total memory: 10485760 (0x0000000000A00000) 1STSEGINUSE Total memory in use: 10485760 (0x0000000000A00000) 1STSEGFREE Total memory free: 0 (0x0000000000000000) 1STSEGLIMIT Allocation limit: 402653184 (0x0000000018000000) NULL
1STGCHTYPE GC History
3STHSTTYPE 02:54:22:055231000 GMT j9mm.136 - Compact start: reason=compact on aggressive collection 3STHSTTYPE 02:54:22:055229000 GMT j9mm.57 - Sweep end 3STHSTTYPE 02:54:22:036054000 GMT j9mm.56 - Sweep start 3STHSTTYPE 02:54:22:036052000 GMT j9mm.94 - Class unloading end: classloadersunloaded=0 classesunloaded=0 3STHSTTYPE 02:54:22:036020000 GMT j9mm.60 - Class unloading start 3STHSTTYPE 02:54:22:036019000 GMT j9mm.55 - Mark end 3STHSTTYPE 02:54:21:083918000 GMT j9mm.54 - Mark start 3STHSTTYPE 02:54:21:083553000 GMT j9mm.474 - GlobalGC start: globalcount=449555 3STHSTTYPE 02:54:21:082688000 GMT j9mm.135 - Exclusive access: exclusiveaccessms=1.235 meanexclusiveaccessms=1.235 threads=0 lastthreadtid=0x0000000001B0EE80 beatenbyotherthread=0 3STHSTTYPE 02:54:21:082687000 GMT j9mm.469 - Allocation failure cycle start: newspace=0/563609600 oldspace=16912384/1691222016 loa=16912384/16912384 requestedbytes=24 3STHSTTYPE 02:54:21:081913000 GMT j9mm.470 - Allocation failure cycle end: newspace=0/563609600 oldspace=16912384/1691222016 loa=16912384/16912384 3STHSTTYPE 02:54:21:081827000 GMT j9mm.468 - Cycle End: type 2 approximateFreeMemorySize 16912384 3STHSTTYPE 02:54:21:079713000 GMT j9mm.560 - LocalGC end: rememberedsetoverflow=0 causedrememberedsetoverflow=0 scancacheoverflow=0 failedflipcount=1 failedflipbytes=40 failedtenurecount=598767 failedtenurebytes=15608320 flipcount=6766908 flipbytes=167440888 newspace=0/563609600 oldspace=16912384/1691222016 loa=16912384/16912384 tenureage=0 3STHSTTYPE 02:54:21:078660000 GMT j9mm.140 - Tilt ratio: 70 3STHSTTYPE 02:54:20:146693000 GMT j9mm.63 - Set scavenger backout flag=true 3STHSTTYPE 02:54:19:833122000 GMT j9mm.64 - LocalGC start: globalcount=449555 scavengecount=450902 weakrefs=0 soft=0 phantom=0 finalizers=0 3STHSTTYPE 02:54:19:833113000 GMT j9mm.63 - Set scavenger backout flag=false 3STHSTTYPE 02:54:19:833112000 GMT j9mm.467 - Cycle Start: type 2 approximateFreeMemorySize 173423520 3STHSTTYPE 02:54:19:832503000 GMT j9mm.135 - Exclusive access: exclusiveaccessms=1.235 meanexclusiveaccessms=1.235 threads=0 lastthreadtid=0x0000000001B0EE80 beatenbyotherthread=1 3STHSTTYPE 02:54:19:832502000 GMT j9mm.469 - Allocation failure cycle start: newspace=0/563609600 oldspace=173423520/1691222016 loa=16912384/16912384 requestedbytes=24 3STHSTTYPE 02:54:19:832501000 GMT j9mm.133 - Allocation failure start: newspace=0/563609600 oldspace=173423520/1691222016 loa=16912384/16912384 requestedbytes=24 3STHSTTYPE 02:54:19:827621000 GMT j9mm.134 - Allocation failure end: newspace=0/563609600 oldspace=173423520/1691222016 loa=16912384/16912384 3STHSTTYPE 02:54:19:827615000 GMT j9mm.470 - Allocation failure cycle end: newspace=0/563609600 oldspace=173423520/1691222016 loa=16912384/16912384 3STHSTTYPE 02:54:19:823292000 GMT j9mm.475 - GlobalGC end: workstackoverflow=0 overflowcount=0 memory=173423544/2254831616 3STHSTTYPE 02:54:19:822090000 GMT j9mm.90 - GlobalGC collect complete 3STHSTTYPE 02:54:19:819752000 GMT j9mm.57 - Sweep end 3STHSTTYPE 02:54:19:795694000 GMT j9mm.56 - Sweep start 3STHSTTYPE 02:54:19:795692000 GMT j9mm.94 - Class unloading end: classloadersunloaded=0 classesunloaded=0 3STHSTTYPE 02:54:19:795653000 GMT j9mm.60 - Class unloading start 3STHSTTYPE 02:54:19:795651000 GMT j9mm.55 - Mark end 3STHSTTYPE 02:54:18:820671000 GMT j9mm.54 - Mark start 3STHSTTYPE 02:54:18:820194000 GMT j9mm.474 - GlobalGC start: globalcount=449554 3STHSTTYPE 02:54:18:819257000 GMT j9mm.135 - Exclusive access: exclusiveaccessms=1.888 meanexclusiveaccessms=1.888 threads=0 lastthreadtid=0x00000000024F8F80 beatenbyotherthread=0 3STHSTTYPE 02:54:18:819256000 GMT j9mm.469 - Allocation failure cycle start: newspace=0/563609600 oldspace=16912384/1691222016 loa=16912384/16912384 requestedbytes=24 3STHSTTYPE 02:54:18:817594000 GMT j9mm.470 - Allocation failure cycle end: newspace=0/563609600 oldspace=16912384/1691222016 loa=16912384/16912384 3STHSTTYPE 02:54:18:817467000 GMT j9mm.468 - Cycle End: type 2 approximateFreeMemorySize 16912384 3STHSTTYPE 02:54:18:812397000 GMT j9mm.560 - LocalGC end: rememberedsetoverflow=0 causedrememberedsetoverflow=0 scancacheoverflow=0 failedflipcount=1 failedflipbytes=48 failedtenurecount=501537 failedtenurebytes=12737760 flipcount=4706799 flipbytes=167521656 newspace=0/563609600 oldspace=16912384/1691222016 loa=16912384/16912384 tenureage=0 3STHSTTYPE 02:54:18:811124000 GMT j9mm.140 - Tilt ratio: 70 3STHSTTYPE 02:54:17:782858000 GMT j9mm.63 - Set scavenger backout flag=true 3STHSTTYPE 02:54:17:489922000 GMT j9mm.64 - LocalGC start: globalcount=449554 scavengecount=450901 weakrefs=0 soft=0 phantom=0 finalizers=0 3STHSTTYPE 02:54:17:489915000 GMT j9mm.63 - Set scavenger backout flag=false 3STHSTTYPE 02:54:17:489914000 GMT j9mm.467 - Cycle Start: type 2 approximateFreeMemorySize 173423544 3STHSTTYPE 02:54:17:489320000 GMT j9mm.135 - Exclusive access: exclusiveaccessms=1.888 meanexclusiveaccessms=1.888 threads=0 lastthreadtid=0x00000000024F8F80 beatenbyotherthread=1 3STHSTTYPE 02:54:17:489319000 GMT j9mm.469 - Allocation failure cycle start: newspace=0/563609600 oldspace=173423544/1691222016 loa=16912384/16912384 requestedbytes=24 3STHSTTYPE 02:54:17:489318000 GMT j9mm.133 - Allocation failure start: newspace=0/563609600 oldspace=173423544/1691222016 loa=16912384/16912384 requestedbytes=24 3STHSTTYPE 02:54:17:484845000 GMT j9mm.134 - Allocation failure end: newspace=0/563609600 oldspace=173423544/1691222016 loa=16912384/16912384 3STHSTTYPE 02:54:17:484839000 GMT j9mm.470 - Allocation failure cycle end: newspace=0/563609600 oldspace=173423544/1691222016 loa=16912384/16912384 3STHSTTYPE 02:54:17:482290000 GMT j9mm.475 - GlobalGC end: workstackoverflow=0 overflowcount=0 memory=173424328/2254831616 3STHSTTYPE 02:54:17:481834000 GMT j9mm.90 - GlobalGC collect complete 3STHSTTYPE 02:54:17:480711000 GMT j9mm.137 - Compact end: bytesmoved=400 3STHSTTYPE 02:54:16:603761000 GMT j9mm.136 - Compact start: reason=compact on aggressive collection 3STHSTTYPE 02:54:16:603758000 GMT j9mm.57 - Sweep end 3STHSTTYPE 02:54:16:583225000 GMT j9mm.56 - Sweep start 3STHSTTYPE 02:54:16:583223000 GMT j9mm.94 - Class unloading end: classloadersunloaded=0 classesunloaded=0 3STHSTTYPE 02:54:16:583185000 GMT j9mm.60 - Class unloading start 3STHSTTYPE 02:54:16:583184000 GMT j9mm.55 - Mark end 3STHSTTYPE 02:54:15:661503000 GMT j9mm.54 - Mark start 3STHSTTYPE 02:54:15:661127000 GMT j9mm.474 - GlobalGC start: globalcount=449553 3STHSTTYPE 02:54:15:660246000 GMT j9mm.135 - Exclusive access: exclusiveaccessms=2.075 meanexclusiveaccessms=2.075 threads=0 lastthreadtid=0x000000000232F980 beatenbyotherthread=0 3STHSTTYPE 02:54:15:660246000 GMT j9mm.469 - Allocation failure cycle start: newspace=0/563609600 oldspace=16912384/1691222016 loa=16912384/16912384 requestedbytes=48 3STHSTTYPE 02:54:15:659426000 GMT j9mm.470 - Allocation failure cycle end: newspace=0/563609600 oldspace=16912384/1691222016 loa=16912384/16912384 3STHSTTYPE 02:54:15:659355000 GMT j9mm.468 - Cycle End: type 2 approximateFreeMemorySize 16912384 3STHSTTYPE 02:54:15:657553000 GMT j9mm.560 - LocalGC end: rememberedsetoverflow=0 causedrememberedsetoverflow=0 scancacheoverflow=0 failedflipcount=1 failedflipbytes=40 failedtenurecount=549662 failedtenurebytes=13145728 flipcount=6808008 flipbytes=167581640 newspace=0/563609600 oldspace=16912384/1691222016 loa=16912384/16912384 tenureage=0 3STHSTTYPE 02:54:15:656448000 GMT j9mm.140 - Tilt ratio: 70 3STHSTTYPE 02:54:14:788093000 GMT j9mm.63 - Set scavenger backout flag=true 3STHSTTYPE 02:54:14:462967000 GMT j9mm.64 - LocalGC start: globalcount=449553 scavengecount=450900 weakrefs=0 soft=0 phantom=0 finalizers=0 3STHSTTYPE 02:54:14:462956000 GMT j9mm.63 - Set scavenger backout flag=false 3STHSTTYPE 02:54:14:462955000 GMT j9mm.467 - Cycle Start: type 2 approximateFreeMemorySize 173423544 3STHSTTYPE 02:54:14:462142000 GMT j9mm.135 - Exclusive access: exclusiveaccessms=2.075 meanexclusiveaccessms=2.075 threads=0 lastthreadtid=0x000000000232F980 beatenbyotherthread=1 3STHSTTYPE 02:54:14:462141000 GMT j9mm.469 - Allocation failure cycle start: newspace=0/563609600 oldspace=173423544/1691222016 loa=16912384/16912384 requestedbytes=48 3STHSTTYPE 02:54:14:462140000 GMT j9mm.133 - Allocation failure start: newspace=0/563609600 oldspace=173423544/1691222016 loa=16912384/16912384 requestedbytes=48 3STHSTTYPE 02:54:14:455610000 GMT j9mm.134 - Allocation failure end: newspace=0/563609600 oldspace=173423544/1691222016 loa=16912384/16912384 3STHSTTYPE 02:54:14:455604000 GMT j9mm.470 - Allocation failure cycle end: newspace=0/563609600 oldspace=173423544/1691222016 loa=16912384/16912384 3STHSTTYPE 02:54:14:451397000 GMT j9mm.475 - GlobalGC end: workstackoverflow=0 overflowcount=0 memory=173423560/2254831616 3STHSTTYPE 02:54:14:449819000 GMT j9mm.90 - GlobalGC collect complete 3STHSTTYPE 02:54:14:446838000 GMT j9mm.57 - Sweep end 3STHSTTYPE 02:54:14:425994000 GMT j9mm.56 - Sweep start 3STHSTTYPE 02:54:14:425991000 GMT j9mm.94 - Class unloading end: classloadersunloaded=0 classesunloaded=0 3STHSTTYPE 02:54:14:425912000 GMT j9mm.60 - Class unloading start 3STHSTTYPE 02:54:14:425910000 GMT j9mm.55 - Mark end 3STHSTTYPE 02:54:13:516165000 GMT j9mm.54 - Mark start 3STHSTTYPE 02:54:13:515762000 GMT j9mm.474 - GlobalGC start: globalcount=449552 3STHSTTYPE 02:54:13:514796000 GMT j9mm.135 - Exclusive access: exclusiveaccessms=0.524 meanexclusiveaccessms=0.524 threads=0 lastthreadtid=0x000000000336F380 beatenbyotherthread=0 3STHSTTYPE 02:54:13:514795000 GMT j9mm.469 - Allocation failure cycle start: newspace=0/563609600 oldspace=16912384/1691222016 loa=16912384/16912384 requestedbytes=16 3STHSTTYPE 02:54:13:513973000 GMT j9mm.470 - Allocation failure cycle end: newspace=0/563609600 oldspace=16912384/1691222016 loa=16912384/16912384 3STHSTTYPE 02:54:13:513910000 GMT j9mm.468 - Cycle End: type 2 approximateFreeMemorySize 16912384 3STHSTTYPE 02:54:13:512489000 GMT j9mm.560 - LocalGC end: rememberedsetoverflow=0 causedrememberedsetoverflow=0 scancacheoverflow=0 failedflipcount=1 failedflipbytes=24 failedtenurecount=497087 failedtenurebytes=11938264 flipcount=4727251 flipbytes=167471096 newspace=0/563609600 oldspace=16912384/1691222016 loa=16912384/16912384 tenureage=0 3STHSTTYPE 02:54:13:511431000 GMT j9mm.140 - Tilt ratio: 70 3STHSTTYPE 02:54:12:656081000 GMT j9mm.63 - Set scavenger backout flag=true 3STHSTTYPE 02:54:12:346257000 GMT j9mm.64 - LocalGC start: globalcount=449552 scavengecount=450899 weakrefs=0 soft=0 phantom=0 finalizers=0 3STHSTTYPE 02:54:12:346246000 GMT j9mm.63 - Set scavenger backout flag=false 3STHSTTYPE 02:54:12:346245000 GMT j9mm.467 - Cycle Start: type 2 approximateFreeMemorySize 173423560 3STHSTTYPE 02:54:12:345549000 GMT j9mm.135 - Exclusive access: exclusiveaccessms=0.524 meanexclusiveaccessms=0.524 threads=0 lastthreadtid=0x000000000336F380 beatenbyotherthread=1 3STHSTTYPE 02:54:12:345549000 GMT j9mm.469 - Allocation failure cycle start: newspace=0/563609600 oldspace=173423560/1691222016 loa=16912384/16912384 requestedbytes=16 3STHSTTYPE 02:54:12:345547000 GMT j9mm.133 - Allocation failure start: newspace=0/563609600 oldspace=173423560/1691222016 loa=16912384/16912384 requestedbytes=16 3STHSTTYPE 02:54:12:340508000 GMT j9mm.134 - Allocation failure end: newspace=0/563609600 oldspace=173423560/1691222016 loa=16912384/16912384 3STHSTTYPE 02:54:12:340501000 GMT j9mm.470 - Allocation failure cycle end: newspace=0/563609600 oldspace=173423560/1691222016 loa=16912384/16912384 3STHSTTYPE 02:54:12:338980000 GMT j9mm.475 - GlobalGC end: workstackoverflow=0 overflowcount=0 memory=173423608/2254831616 3STHSTTYPE 02:54:12:337846000 GMT j9mm.90 - GlobalGC collect complete 3STHSTTYPE 02:54:12:335403000 GMT j9mm.137 - Compact end: bytesmoved=0 3STHSTTYPE 02:54:11:368162000 GMT j9mm.136 - Compact start: reason=compact on aggressive collection 3STHSTTYPE 02:54:11:368159000 GMT j9mm.57 - Sweep end 3STHSTTYPE 02:54:11:339565000 GMT j9mm.56 - Sweep start 3STHSTTYPE 02:54:11:339562000 GMT j9mm.94 - Class unloading end: classloadersunloaded=0 classesunloaded=0 3STHSTTYPE 02:54:11:339519000 GMT j9mm.60 - Class unloading start 3STHSTTYPE 02:54:11:339517000 GMT j9mm.55 - Mark end 3STHSTTYPE 02:54:10:347981000 GMT j9mm.54 - Mark start 3STHSTTYPE 02:54:10:347506000 GMT j9mm.474 - GlobalGC start: globalcount=449551 3STHSTTYPE 02:54:10:346615000 GMT j9mm.135 - Exclusive access: exclusiveaccessms=0.790 meanexclusiveaccessms=0.790 threads=0 lastthreadtid=0x000000000013F880 beatenbyotherthread=0 3STHSTTYPE 02:54:10:346615000 GMT j9mm.469 - Allocation failure cycle start: newspace=0/563609600 oldspace=16912384/1691222016 loa=16912384/16912384 requestedbytes=48 3STHSTTYPE 02:54:10:345375000 GMT j9mm.470 - Allocation failure cycle end: newspace=0/563609600 oldspace=16912384/1691222016 loa=16912384/16912384 3STHSTTYPE 02:54:10:345300000 GMT j9mm.468 - Cycle End: type 2 approximateFreeMemorySize 16912384 3STHSTTYPE 02:54:10:343887000 GMT j9mm.560 - LocalGC end: rememberedsetoverflow=0 causedrememberedsetoverflow=0 scancacheoverflow=0 failedflipcount=1 failedflipbytes=4944 failedtenurecount=565999 failedtenurebytes=13399296 flipcount=6811314 flipbytes=167451952 newspace=0/563609600 oldspace=16912384/1691222016 loa=16912384/16912384 tenureage=0 3STHSTTYPE 02:54:10:342240000 GMT j9mm.140 - Tilt ratio: 70 3STHSTTYPE 02:54:09:435454000 GMT j9mm.63 - Set scavenger backout flag=true 3STHSTTYPE 02:54:09:127901000 GMT j9mm.64 - LocalGC start: globalcount=449551 scavengecount=450898 weakrefs=0 soft=0 phantom=0 finalizers=0 3STHSTTYPE 02:54:09:127890000 GMT j9mm.63 - Set scavenger backout flag=false 3STHSTTYPE 02:54:09:127888000 GMT j9mm.467 - Cycle Start: type 2 approximateFreeMemorySize 173423592 3STHSTTYPE 02:54:09:127205000 GMT j9mm.135 - Exclusive access: exclusiveaccessms=0.790 meanexclusiveaccessms=0.790 threads=0 lastthreadtid=0x000000000013F880 beatenbyotherthread=1 3STHSTTYPE 02:54:09:127204000 GMT j9mm.469 - Allocation failure cycle start: newspace=0/563609600 oldspace=173423592/1691222016 loa=16912384/16912384 requestedbytes=48 3STHSTTYPE 02:54:09:127202000 GMT j9mm.133 - Allocation failure start: newspace=0/563609600 oldspace=173423592/1691222016 loa=16912384/16912384 requestedbytes=48 3STHSTTYPE 02:54:09:123011000 GMT j9mm.134 - Allocation failure end: newspace=0/563609600 oldspace=173423592/1691222016 loa=16912384/16912384 3STHSTTYPE 02:54:09:123004000 GMT j9mm.470 - Allocation failure cycle end: newspace=0/563609600 oldspace=173423592/1691222016 loa=16912384/16912384 3STHSTTYPE 02:54:09:120004000 GMT j9mm.475 - GlobalGC end: workstackoverflow=0 overflowcount=0 memory=173423608/2254831616 3STHSTTYPE 02:54:09:119532000 GMT j9mm.90 - GlobalGC collect complete 3STHSTTYPE 02:54:09:118622000 GMT j9mm.57 - Sweep end 3STHSTTYPE 02:54:09:097479000 GMT j9mm.56 - Sweep start 3STHSTTYPE 02:54:09:097477000 GMT j9mm.94 - Class unloading end: classloadersunloaded=0 classesunloaded=0 3STHSTTYPE 02:54:09:097439000 GMT j9mm.60 - Class unloading start 3STHSTTYPE 02:54:09:097438000 GMT j9mm.55 - Mark end 3STHSTTYPE 02:54:08:182706000 GMT j9mm.54 - Mark start 3STHSTTYPE 02:54:08:182208000 GMT j9mm.474 - GlobalGC start: globalcount=449550 3STHSTTYPE 02:54:08:181288000 GMT j9mm.135 - Exclusive access: exclusiveaccessms=2.021 meanexclusiveaccessms=2.021 threads=0 lastthreadtid=0x0000000001BC1680 beatenbyotherthread=0 3STHSTTYPE 02:54:08:181287000 GMT j9mm.469 - Allocation failure cycle start: newspace=0/563609600 oldspace=16912384/1691222016 loa=16912384/16912384 requestedbytes=16 3STHSTTYPE 02:54:08:180290000 GMT j9mm.470 - Allocation failure cycle end: newspace=0/563609600 oldspace=16912384/1691222016 loa=16912384/16912384 3STHSTTYPE 02:54:08:180220000 GMT j9mm.468 - Cycle End: type 2 approximateFreeMemorySize 16912384 3STHSTTYPE 02:54:08:177552000 GMT j9mm.560 - LocalGC end: rememberedsetoverflow=0 causedrememberedsetoverflow=0 scancacheoverflow=0 failedflipcount=1 failedflipbytes=24 failedtenurecount=496486 failedtenurebytes=12047936 flipcount=4725763 flipbytes=167523008 newspace=0/563609600 oldspace=16912384/1691222016 loa=16912384/16912384 tenureage=0 3STHSTTYPE 02:54:08:176461000 GMT j9mm.140 - Tilt ratio: 70 3STHSTTYPE 02:54:07:289277000 GMT j9mm.63 - Set scavenger backout flag=true 3STHSTTYPE 02:54:06:975539000 GMT j9mm.64 - LocalGC start: globalcount=449550 scavengecount=450897 weakrefs=0 soft=0 phantom=0 finalizers=0 3STHSTTYPE 02:54:06:975528000 GMT j9mm.63 - Set scavenger backout flag=false 3STHSTTYPE 02:54:06:975527000 GMT j9mm.467 - Cycle Start: type 2 approximateFreeMemorySize 173423608 3STHSTTYPE 02:54:06:974840000 GMT j9mm.135 - Exclusive access: exclusiveaccessms=2.021 meanexclusiveaccessms=2.021 threads=0 lastthreadtid=0x0000000001BC1680 beatenbyotherthread=1 3STHSTTYPE 02:54:06:974840000 GMT j9mm.469 - Allocation failure cycle start: newspace=0/563609600 oldspace=173423608/1691222016 loa=16912384/16912384 requestedbytes=16 3STHSTTYPE 02:54:06:974838000 GMT j9mm.133 - Allocation failure start: newspace=0/563609600 oldspace=173423608/1691222016 loa=16912384/16912384 requestedbytes=16 3STHSTTYPE 02:54:06:969535000 GMT j9mm.134 - Allocation failure end: newspace=0/563609600 oldspace=173423608/1691222016 loa=16912384/16912384 3STHSTTYPE 02:54:06:969529000 GMT j9mm.470 - Allocation failure cycle end: newspace=0/563609600 oldspace=173423608/1691222016 loa=16912384/16912384 3STHSTTYPE 02:54:06:967533000 GMT j9mm.475 - GlobalGC end: workstackoverflow=0 overflowcount=0 memory=173423632/2254831616 3STHSTTYPE 02:54:06:965992000 GMT j9mm.90 - GlobalGC collect complete 3STHSTTYPE 02:54:06:962865000 GMT j9mm.137 - Compact end: bytesmoved=27520 3STHSTTYPE 02:54:06:035514000 GMT j9mm.136 - Compact start: reason=compact on aggressive collection 3STHSTTYPE 02:54:06:035511000 GMT j9mm.57 - Sweep end 3STHSTTYPE 02:54:06:014101000 GMT j9mm.56 - Sweep start 3STHSTTYPE 02:54:06:014098000 GMT j9mm.94 - Class unloading end: classloadersunloaded=0 classesunloaded=0 3STHSTTYPE 02:54:06:014046000 GMT j9mm.60 - Class unloading start 3STHSTTYPE 02:54:06:014044000 GMT j9mm.55 - Mark end 3STHSTTYPE 02:54:05:095268000 GMT j9mm.54 - Mark start 3STHSTTYPE 02:54:05:094848000 GMT j9mm.474 - GlobalGC start: globalcount=449549 3STHSTTYPE 02:54:05:094009000 GMT j9mm.135 - Exclusive access: exclusiveaccessms=0.767 meanexclusiveaccessms=0.767 threads=0 lastthreadtid=0x0000000003360480 beatenbyotherthread=0 3STHSTTYPE 02:54:05:094009000 GMT j9mm.469 - Allocation failure cycle start: newspace=0/563609600 oldspace=16912384/1691222016 loa=16912384/16912384 requestedbytes=24 3STHSTTYPE 02:54:05:093195000 GMT j9mm.470 - Allocation failure cycle end: newspace=0/563609600 oldspace=16912384/1691222016 loa=16912384/16912384 3STHSTTYPE 02:54:05:093134000 GMT j9mm.468 - Cycle End: type 2 approximateFreeMemorySize 16912384 NULL
NULL ------------------------------------------------------------------------ 0SECTION LOCKS subcomponent dump routine NULL =============================== NULL
1LKPOOLINFO Monitor pool info: 2LKPOOLTOTAL Current total number of monitors: 2443 ....................

dmitripivkine commented 2 years ago

Ok, this is exact scenario I expected (Scavenge->Scavenge Backout->Global GC->repeat). Excessive GC detection does not trigger OOM. The only difference from scenario we observed before it is running in container.

dmitripivkine commented 2 years ago

@jackin853

dmitripivkine commented 2 years ago

@jackin853 I found an issue https://github.com/eclipse/omr/issues/5714 Unfortunately it has not been fixed yet. We will boost priority. Sorry about this.

jackin853 commented 2 years ago

@dmitripivkine I Know, thank you very much, but I don’t know why GC enters the loop.

dmitripivkine commented 2 years ago

@dmitripivkine I Know, thank you very much, but I don’t know why GC enters the loop.

This is "Object heap" OOM situation. Tenure and Nursery are full. However pure condition of unresolvable allocation failure has not reached - every GC is releasing a little bit memory to be enough to allocate a few objects before GC is required again. This situation is known as Excessive GC when vast amount of processing resources is taken by GC (90%+) with very little result. Excessive GC condition must be detected and trigger OOM regardless was object allocation successful after GC. Unfortunately in this particular scenario (attempt to Scavenge, failed, Backout Scavenge, percolate to Global GC) some metrics used for Excessive GC are reset and it prevents Excessive GC condition to be detected. So application does not have enough heap space to run but can not throw OOM as expected but "hangs" (not really, it progresses but very very slow spending 99% of processor time to execute GC). There is general advice increase heap size or/and investigate heap content for possible memory leaks.

dmitripivkine commented 1 year ago

duplicate of https://github.com/eclipse/omr/issues/5714

dmitripivkine commented 1 year ago

Closing as duplicate, fix is coming https://github.com/eclipse/omr/pull/7068