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

JDK19 java/nio/channels/FileChannel/largeMemory/LargeGatheringWrite.java OutOfMemoryError: native memory exhausted #15626

Open JasonFengJ9 opened 2 years ago

JasonFengJ9 commented 2 years ago

Failure link

From an internal build(ub18s390xrt-1-1):

openjdk version "19" 2022-09-20
IBM Semeru Runtime Open Edition 19+31 (build 19+31)
Eclipse OpenJ9 VM 19+31 (build master-e70b78378, JRE 19 Linux s390x-64-Bit Compressed References 20220919_19 (JIT enabled, AOT enabled)
OpenJ9   - e70b78378
OMR      - 6061e7ce4
JCL      - 5da3ac5d21 based on jdk-19+31)

Rerun in Grinder - Change TARGET to run only the failed test targets.

Optional info

Failure output (captured from console output)

[2022-07-23T18:29:56.245Z] variation: Mode150
[2022-07-23T18:29:56.245Z] JVM_OPTIONS:  -XX:+UseCompressedOops 

[2022-07-23T18:33:18.678Z] TEST: java/nio/channels/FileChannel/largeMemory/LargeGatheringWrite.java

[2022-07-23T18:33:18.679Z] java.lang.OutOfMemoryError: native memory exhausted
[2022-07-23T18:33:18.679Z]  at java.base/jdk.internal.misc.Unsafe.allocateDBBMemory(Native Method)
[2022-07-23T18:33:18.679Z]  at java.base/java.nio.DirectByteBuffer.<init>(DirectByteBuffer.java:137)
[2022-07-23T18:33:18.679Z]  at java.base/java.nio.ByteBuffer.allocateDirect(ByteBuffer.java:342)
[2022-07-23T18:33:18.679Z]  at java.base/sun.nio.ch.Util.getTemporaryDirectBuffer(Util.java:245)
[2022-07-23T18:33:18.679Z]  at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:208)
[2022-07-23T18:33:18.679Z]  at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:164)
[2022-07-23T18:33:18.679Z]  at java.base/sun.nio.ch.FileChannelImpl.write(FileChannelImpl.java:341)
[2022-07-23T18:33:18.679Z]  at java.base/java.nio.channels.FileChannel.write(FileChannel.java:451)
[2022-07-23T18:33:18.679Z]  at LargeGatheringWrite.main(LargeGatheringWrite.java:102)
[2022-07-23T18:33:18.679Z]  at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
[2022-07-23T18:33:18.679Z]  at java.base/java.lang.reflect.Method.invoke(Method.java:578)
[2022-07-23T18:33:18.679Z]  at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
[2022-07-23T18:33:18.679Z]  at java.base/java.lang.Thread.run(Thread.java:1573)
[2022-07-23T18:33:18.679Z] 
[2022-07-23T18:33:18.679Z] JavaTest Message: Test threw exception: java.lang.OutOfMemoryError: native memory exhausted

[2022-07-23T18:45:05.238Z] Test results: passed: 390; failed: 1
[2022-07-23T18:45:46.785Z] Report written to /home/jenkins/workspace/Test_openjdk19_j9_extended.openjdk_s390x_linux/jvmtest/openjdk/report/html/report.html
[2022-07-23T18:45:46.785Z] Results written to /home/jenkins/workspace/Test_openjdk19_j9_extended.openjdk_s390x_linux/aqa-tests/TKG/output_16585995717451/jdk_nio_0/work
[2022-07-23T18:45:46.785Z] Error: Some tests failed or other problems occurred.
[2022-07-23T18:45:46.785Z] 
[2022-07-23T18:45:46.785Z] jdk_nio_0_FAILED
pshipton commented 2 years ago

The failure doesn't really make sense given the size of the JVM and memory available on the machine. There is no core available so not sure how much DBB memory it was trying to allocate. Of course the memory stats from the machine are what is available now and not what was available at the time the test was running.

MemTotal:        3912696 kB

              total        used        free      shared  buff/cache   available
Mem:        3912696      222048      119268         128     3571380     3595892
Swap:        998396       86624      911772

1MEMUSER       JRE: 7,685,326,072 bytes / 5505 allocations

5MEMUSER       |  |  |  +--Direct Byte Buffers: 2,684,355,328 bytes / 9 allocations

1STHEAPTYPE    Object Memory
NULL           id                 start              end                size               space/region
1STHEAPSPACE   0x000003FFA00A9CD0         --                 --                 --         Generational
1STHEAPREGION  0x000003FFA00AA4C0 0x000003FE9F000000 0x000003FEFA910000 0x000000005B910000 Generational/Tenured Region
1STHEAPREGION  0x000003FFA00AA130 0x000003FF9ED40000 0x000003FF9EE70000 0x0000000000130000 Generational/Nursery Region
1STHEAPREGION  0x000003FFA00A9DA0 0x000003FF9EE70000 0x000003FF9F000000 0x0000000000190000 Generational/Nursery Region
NULL
1STHEAPTOTAL   Total memory:                  1539112960 (0x000000005BBD0000)
1STHEAPINUSE   Total memory in use:           1077595048 (0x00000000403ACBA8)
1STHEAPFREE    Total memory free:              461517912 (0x000000001B823458)

1STGCHTYPE     GC History
3STHSTTYPE     18:48:41:365751183 GMT j9mm.134 -   Allocation failure end: newspace=1182040/2883584 oldspace=460912264/1536229376 loa=92174336/92174336
3STHSTTYPE     18:48:40:987203828 GMT j9mm.470 -   Allocation failure cycle end: newspace=1182040/2883584 oldspace=460912264/1536229376 loa=92174336/92174336
3STHSTTYPE     18:48:40:987173330 GMT j9mm.475 -   GlobalGC end: workstackoverflow=0 overflowcount=0 memory=462094304/1539112960
3STHSTTYPE     18:48:40:986598473 GMT j9mm.90 -   GlobalGC collect complete
3STHSTTYPE     18:48:40:986555486 GMT j9mm.137 -   Compact end: bytesmoved=1717704
3STHSTTYPE     18:48:40:980226974 GMT j9mm.136 -   Compact start: reason=compact to meet allocation
3STHSTTYPE     18:48:40:980225363 GMT j9mm.57 -   Sweep end
3STHSTTYPE     18:48:40:979892246 GMT j9mm.56 -   Sweep start
3STHSTTYPE     18:48:40:979889373 GMT j9mm.94 -   Class unloading end: classloadersunloaded=0 classesunloaded=0
3STHSTTYPE     18:48:40:979877093 GMT j9mm.60 -   Class unloading start
3STHSTTYPE     18:48:40:979875777 GMT j9mm.55 -   Mark end
3STHSTTYPE     18:48:40:966400443 GMT j9mm.54 -   Mark start
3STHSTTYPE     18:48:40:966368397 GMT j9mm.474 -   GlobalGC start: globalcount=0
3STHSTTYPE     18:48:40:966359412 GMT j9mm.135 -   Exclusive access: exclusiveaccessms=0.040 meanexclusiveaccessms=0.033 threads=1 lastthreadtid=0x000003FE7C002F80 beatenbyotherthread=0
3STHSTTYPE     18:48:40:966358767 GMT j9mm.469 -   Allocation failure cycle start: newspace=1087008/2883584 oldspace=4668528/6291456 loa=315392/315392 requestedbytes=1073741848
3STHSTTYPE     18:48:40:966350533 GMT j9mm.470 -   Allocation failure cycle end: newspace=1087008/2883584 oldspace=4668528/6291456 loa=315392/315392
3STHSTTYPE     18:48:40:966339090 GMT j9mm.468 -   Cycle End: type 2 approximateFreeMemorySize 5755536
3STHSTTYPE     18:48:40:966324009 GMT j9mm.560 -   LocalGC end: rememberedsetoverflow=0 causedrememberedsetoverflow=0 scancacheoverflow=0 failedflipcount=0 failedflipbytes=0 failedtenurecount=0 failedtenurebytes=0 flipcount=7519 flipbytes=456360 newspace=1087008/2883584 oldspace=4668528/6291456 loa=315392/315392 tenureage=0
3STHSTTYPE     18:48:40:966273694 GMT j9mm.140 -   Tilt ratio: 54
3STHSTTYPE     18:48:40:963367443 GMT j9mm.64 -   LocalGC start: globalcount=0 scavengecount=6 weakrefs=0 soft=0 phantom=0 finalizers=0
3STHSTTYPE     18:48:40:963352471 GMT j9mm.467 -   Cycle Start: type 2 approximateFreeMemorySize 4970576