search

ibmruntimes / Semeru-Runtimes

Issue repo for all things IBM Semeru Runtimes
14 stars 4 forks source link

Abnormal usage of memory when using Java 17 (JRE>VM>Other) #32

Closed tschurins closed 2 years ago

tschurins commented 2 years ago

We are migrating our application from java 8 to java 17. Our application runs in OpenLiberty. Our target is to use the official OpenLiberty docker image (open-liberty:22.0.0.3-full-java17-openj9) which comes with IBM Semeru JDK and OpenJ9. When running our application with this image, we detected an abnormal usage of memory (around 8Gb instead of 4Gb).

We did some investigations: in that image, we loaded a different jdk to see the impact:

We couldn't find older IBM semeru JDK (12, 13, 14, 15) to see from when the problem is present.

We took heap dumps and compare them, but there was no real difference. We took java dumps to see how the memory was used. Comparing java 8 and java 17, the main difference between the two is the JRE>VM>Other part of the memory (which is around 2Mb with java 8, but takes 4Gb with java 17):

Java 8 memory:

0SECTION       NATIVEMEMINFO subcomponent dump routine
NULL           =================================
1MEMUSER       JRE: 6,242,121,504 bytes / 47322 allocations
2MEMUSER       +--VM: 5,849,829,416 bytes / 43056 allocations
2MEMUSER       |  |
3MEMUSER       |  +--Classes: 228,686,400 bytes / 23577 allocations
2MEMUSER       |  |
3MEMUSER       |  +--Memory Manager (GC): 5,431,847,560 bytes / 3027 allocations
4MEMUSER       |  |  +--Java Heap: 5,318,438,912 bytes / 1 allocation
4MEMUSER       |  |  +--Other: 113,408,648 bytes / 3026 allocations
2MEMUSER       |  |
3MEMUSER       |  +--Threads: 57,151,848 bytes / 902 allocations
4MEMUSER       |  |  +--Java Stack: 4,276,936 bytes / 172 allocations
4MEMUSER       |  |  +--Native Stack: 51,511,296 bytes / 173 allocations
4MEMUSER       |  |  +--Other: 1,363,616 bytes / 557 allocations
2MEMUSER       |  |
3MEMUSER       |  +--Trace: 1,650,136 bytes / 749 allocations
2MEMUSER       |  |
3MEMUSER       |  +--JVMTI: 63,096 bytes / 49 allocations
4MEMUSER       |  |  +--JVMTI Allocate(): 176 bytes / 1 allocation
4MEMUSER       |  |  +--Other: 62,920 bytes / 48 allocations
2MEMUSER       |  |
3MEMUSER       |  +--JNI: 6,539,576 bytes / 13213 allocations
2MEMUSER       |  |
3MEMUSER       |  +--Port Library: 121,236,832 bytes / 96 allocations
4MEMUSER       |  |  +--Unused <32bit allocation regions: 121,221,312 bytes / 1 allocation
4MEMUSER       |  |  +--Other: 15,520 bytes / 95 allocations
2MEMUSER       |  |
3MEMUSER       |  +--Other: 2,653,968 bytes / 1443 allocations
1MEMUSER       |
2MEMUSER       +--JIT: 389,923,832 bytes / 3933 allocations
3MEMUSER       |  +--JIT Code Cache: 268,435,456 bytes / 1 allocation
3MEMUSER       |  +--JIT Data Cache: 27,263,808 bytes / 13 allocations
3MEMUSER       |  +--Other: 94,224,568 bytes / 3919 allocations
1MEMUSER       |
2MEMUSER       +--Class Libraries: 2,368,256 bytes / 333 allocations
2MEMUSER       |  |
3MEMUSER       |  +--VM Class Libraries: 2,368,256 bytes / 333 allocations
3MEMUSER       |  |  |
4MEMUSER       |  |  +--sun.misc.Unsafe: 1,305,928 bytes / 71 allocations
5MEMUSER       |  |  |  +--Direct Byte Buffers: 351,688 bytes / 47 allocations
5MEMUSER       |  |  |  +--Other: 954,240 bytes / 24 allocations
3MEMUSER       |  |  |
4MEMUSER       |  |  +--Other: 1,062,328 bytes / 262 allocations

Java 17 memory:

0SECTION       NATIVEMEMINFO subcomponent dump routine
NULL           =================================
1MEMUSER       JRE: 10,626,766,960 bytes / 1666188 allocations
1MEMUSER       |
2MEMUSER       +--VM: 10,219,319,640 bytes / 1661316 allocations
2MEMUSER       |  |
3MEMUSER       |  +--Classes: 279,747,080 bytes / 24134 allocations
4MEMUSER       |  |  +--Shared Class Cache: 59,769,024 bytes / 4 allocations
4MEMUSER       |  |  +--Other: 219,978,056 bytes / 24130 allocations
2MEMUSER       |  |
3MEMUSER       |  +--Modules: 3,823,424 bytes / 18363 allocations
2MEMUSER       |  |
3MEMUSER       |  +--Memory Manager (GC): 5,432,546,184 bytes / 3317 allocations
4MEMUSER       |  |  +--Java Heap: 5,318,438,912 bytes / 1 allocation
4MEMUSER       |  |  +--Other: 114,107,272 bytes / 3316 allocations
2MEMUSER       |  |
3MEMUSER       |  +--Threads: 58,952,968 bytes / 921 allocations
4MEMUSER       |  |  +--Java Stack: 4,028,864 bytes / 180 allocations
4MEMUSER       |  |  +--Native Stack: 53,608,448 bytes / 181 allocations
4MEMUSER       |  |  +--Other: 1,315,656 bytes / 560 allocations
2MEMUSER       |  |
3MEMUSER       |  +--Trace: 1,670,016 bytes / 767 allocations
2MEMUSER       |  |
3MEMUSER       |  +--JVMTI: 63,104 bytes / 49 allocations
4MEMUSER       |  |  +--JVMTI Allocate(): 184 bytes / 1 allocation
4MEMUSER       |  |  +--Other: 62,920 bytes / 48 allocations
2MEMUSER       |  |
3MEMUSER       |  +--JNI: 7,606,792 bytes / 19532 allocations
2MEMUSER       |  |
3MEMUSER       |  +--Port Library: 119,969,496 bytes / 79 allocations
4MEMUSER       |  |  +--Unused <32bit allocation regions: 119,957,944 bytes / 1 allocation
4MEMUSER       |  |  +--Other: 11,552 bytes / 78 allocations
2MEMUSER       |  |
3MEMUSER       |  +--Other: 4,314,940,576 bytes / 1594154 allocations
1MEMUSER       |
2MEMUSER       +--JIT: 406,340,832 bytes / 4703 allocations
3MEMUSER       |  +--JIT Code Cache: 268,435,456 bytes / 1 allocation
3MEMUSER       |  +--JIT Data Cache: 29,361,024 bytes / 14 allocations
3MEMUSER       |  +--Other: 108,544,352 bytes / 4688 allocations
1MEMUSER       |
2MEMUSER       +--Class Libraries: 1,106,488 bytes / 169 allocations
2MEMUSER       |  |
3MEMUSER       |  +--VM Class Libraries: 1,106,488 bytes / 169 allocations
3MEMUSER       |  |  |
4MEMUSER       |  |  +--sun.misc.Unsafe: 889,192 bytes / 122 allocations
5MEMUSER       |  |  |  +--Direct Byte Buffers: 694,616 bytes / 73 allocations
5MEMUSER       |  |  |  +--Other: 194,576 bytes / 49 allocations
3MEMUSER       |  |  |
4MEMUSER       |  |  +--Other: 217,296 bytes / 47 allocations

Unfortunately, we were not able to determine what this JRE>VM>Other part of the memory was containing. Here are the java dumps: javacore.zip

Any tips are welcome.

pshipton commented 2 years ago

Not sure it's worth the effort to try them, but FYI JVMs from adoptopenjdk.net pre-dated Semeru builds. You can find releases for Java 12- 16 there. https://adoptopenjdk.net/archive.html?variant=openjdk16&jvmVariant=openj9

Besides the tracking used to create the summary in the javacore, OpenJ9 tracks it's non-virtual memory allocations. There are two possibilities to help track it down. 1) Run with the following JVM options, which prints a summary of the memory allocations from each code location every 99999'th time memory is allocated. The number can be adjusted depending on how much output occurs. Compare between jdk11 and jdk17 to identify the extra allocations. -Xcheck:memory:quick,noscan,callsite=99999

2) Create a system core file similarly to how the javacore files were created. Open the system core using jdmpview -core <core> and run !findallcallsites to print a summary of memory allocations done from each location in the code, from biggest to smallest.

tschurins commented 2 years ago

Here is the result of using jdmpview on the java 17 run:

> !findallcallsites
  total alloc  | largest
blocks | bytes | bytes | callsite
-------+-------+-------+-------+-------+-------+-------+-------+-------+-------
 318378 1411047472    4432 ../../../../../openj9/runtime/vm/extendedMessageNPE.cpp:608
 318378 1411047472    4432 ../../../../../openj9/runtime/vm/extendedMessageNPE.cpp:609
 318378 1352466064    4248 ../../../../../openj9/runtime/vm/extendedMessageNPE.cpp:619
   4912 224301400 2097240 ../../../../../openj9/runtime/vm/segment.c:253
 318378 94239800     296 ../../../../../openj9/runtime/vm/extendedMessageNPE.cpp:604
   6725 83964824  621616 ../../../../../openj9/runtime/vm/segment.c:248
 318378 81504640     256 ../../../../../openj9/runtime/vm/extendedMessageNPE.cpp:637
      5 19652560 3930512 ../../../../../../omr/gc/base/WorkPackets.cpp:179
   1425 6210760  601280 ../../../../../openj9/runtime/gc_base/StringTable.cpp:86

Comparing with the java 11 run:

> !findallcallsites
  total alloc  | largest
blocks | bytes | bytes | callsite
-------+-------+-------+-------+-------+-------+-------+-------+-------+-------
   4997 210848488 2097240 ../../../../../openj9/runtime/vm/segment.c:253
   7115 83933648  621616 ../../../../../openj9/runtime/vm/segment.c:248
      5 19652560 3930512 ../../../../../omr/gc/base/WorkPackets.cpp:179
   1427 6216216  601280 ../../../../../openj9/runtime/gc_base/StringTable.cpp:86

We clearly see that this extendedMessageNPE.cpp is the culprit. The numbers also matches, number of allocations and total memory are roughly the same as the JRE>VM>Other memory.

pshipton commented 2 years ago

This is being fixed via https://github.com/eclipse-openj9/openj9/pull/15550

tschurins commented 2 years ago

Thanks for the quick fix! We will test again when available.

tschurins commented 2 years ago

Hello, We have tested with version 17.0.4+8 and everything is fine - memory consumption is same as for java 8 and java 11. Thanks!