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

[Loom] failure related with Scavenger Backout in Skynet #16538

Closed LinHu2016 closed 1 year ago

LinHu2016 commented 1 year ago

the test failure can be reproduced with the below settings ./java -Xmx320M -Xms320M -Xmn16M --enable-preview -Xint -verbose:gc -XXgc:verifyContinuationList -Xgc:noConcurrentMarkKO -Xnocompressedrefs -cp /home/openj9-openjdk-jdk19/test/jdk/java/lang/Thread/virtual/stress Skynet

looks like relate with scavenge backout

<exclusive-start id="1464" timestamp="2023-01-09T12:00:38.725" intervalms="274.586">
  <response-info timems="1.613" idlems="0.821" threads="1" lastid="00007FB10400B100" lastname="ForkJoinPool-1-worker-5" />
</exclusive-start>
<af-start id="1465" threadId="00007FB110018548" totalBytesRequested="72" timestamp="2023-01-09T12:00:38.725" intervalms="274.622" type="nursery" />
<cycle-start id="1466" type="scavenge" contextid="0" timestamp="2023-01-09T12:00:38.725" intervalms="281.677" />
<gc-start id="1467" type="scavenge" contextid="1466" timestamp="2023-01-09T12:00:38.725">
  <mem-info id="1468" free="3272040" total="335544320" percent="0">
    <mem type="nursery" free="0" total="16777216" percent="0">
      <mem type="allocate" free="0" total="8388608" percent="0" />
      <mem type="survivor" free="0" total="8388608" percent="0" />
    </mem>
    <mem type="tenure" free="3272040" total="318767104" percent="1">
      <mem type="soa" free="84328" total="315579392" percent="0" />
      <mem type="loa" free="3187712" total="3187712" percent="100" />
    </mem>
    <remembered-set count="791" />
  </mem-info>
</gc-start>
<allocation-stats totalBytes="194264" >
  <allocated-bytes non-tlh="40" tlh="194224" />
  <largest-consumer threadName="ForkJoinPool-1-worker-1" threadId="00007FB16C337800" bytes="77704" />
</allocation-stats>
<gc-op id="1469" type="scavenge" timems="24.552" contextid="1466" timestamp="2023-01-09T12:00:38.749">
  <scavenger-info tenureage="1" tenuremask="7ffe" tiltratio="50" />
  <memory-copied type="nursery" objects="117588" bytes="8246440" bytesdiscarded="139248" />
  <memory-copied type="tenure" objects="1886" bytes="77008" bytesdiscarded="88" />
  <copy-failed type="nursery" objects="1" bytes="40" />
  <copy-failed type="tenure" objects="113697" bytes="7982992" />
  <ownableSynchronizers candidates="26" cleared="0" />
  <warning details="aborted collection due to insufficient free space" />
</gc-op>
<gc-end id="1470" type="scavenge" contextid="1466" durationms="24.955" usertimems="49.591" systemtimems="0.017" stalltimems="144.913" timestamp="2023-01-09T12:00:38.750" activeThreads="8">
  <mem-info id="1471" free="3187712" total="335544320" percent="0">
    <mem type="nursery" free="0" total="16777216" percent="0">
      <mem type="allocate" free="0" total="8388608" percent="0" />
      <mem type="survivor" free="0" total="8388608" percent="0" />
    </mem>
    <mem type="tenure" free="3187712" total="318767104" percent="1" macro-fragmented="2160235">
      <mem type="soa" free="0" total="315579392" percent="0" />
      <mem type="loa" free="3187712" total="3187712" percent="100" />
    </mem>
    <remembered-set count="791" />
  </mem-info>
</gc-end>
<cycle-end id="1472" type="scavenge" contextid="1466" timestamp="2023-01-09T12:00:38.750" />
<percolate-collect id="1473" from="nursery" to="global" reason="failed tenure threshold reached" timestamp="2023-01-09T12:00:38.750"/>
<cycle-start id="1474" type="global" contextid="0" timestamp="2023-01-09T12:00:38.750" intervalms="299.822" />
<gc-start id="1475" type="global" contextid="1474" timestamp="2023-01-09T12:00:38.750">
  <mem-info id="1476" free="3187712" total="335544320" percent="0">
    <mem type="nursery" free="0" total="16777216" percent="0">
      <mem type="allocate" free="0" total="8388608" percent="0" />
      <mem type="survivor" free="0" total="8388608" percent="0" />
    </mem>
    <mem type="tenure" free="3187712" total="318767104" percent="1">
      <mem type="soa" free="0" total="315579392" percent="0" />
      <mem type="loa" free="3187712" total="3187712" percent="100" />
    </mem>
    <remembered-set count="791" />
  </mem-info>
</gc-start>
<allocation-stats totalBytes="0" >
  <allocated-bytes non-tlh="0" tlh="0" />
</allocation-stats>
Attempt to access continuation object located outside of heap (stack allocated?) 00007FB16C34E800
Unhandled exception
Type=Segmentation error vmState=0x00020002
J9Generic_Signal_Number=00000018 Signal_Number=0000000b Error_Value=00000000 Signal_Code=00000001
Handler1=00007FB171C36010 Handler2=00007FB1728EB340 InaccessibleAddress=00000000000AAEEA
RDI=00007FB16C036C10 RSI=0000000000000001 RAX=00007FB16C027720 RBX=00007FB11C005958
RCX=00000000000AAEEA RDX=00000000000AAED2 R8=0000000000000090 R9=000000000002818A
R10=0000100000000000 R11=000000001006063C R12=00007FB16C087DE0 R13=0000000000000001
R14=00007FB13B287B30 R15=0000000000000007
RIP=00007FB170887C96 GS=0000 FS=0000 RSP=00007FB13B287A70
EFlags=0000000000010216 CS=0033 RBP=00000000000AAED2 ERR=0000000000000004
TRAPNO=000000000000000E OLDMASK=0000000000000000 CR2=00000000000AAEEA
xmm0 0000000000000000 (f: 0.000000, d: 0.000000e+00)
xmm1 39316b646a2d6b64 (f: 1781361536.000000, d: 3.354874e-33)
xmm2 2f6176616a5f6575 (f: 1784636800.000000, d: 1.840923e-80)
xmm3 646a2d6b646a6e65 (f: 1684696704.000000, d: 5.179577e+175)
xmm4 00007fb16bf359c4 (f: 1811110400.000000, d: 6.936682e-310)
xmm5 0000000000000000 (f: 0.000000, d: 0.000000e+00)
xmm6 00007fb158082628 (f: 1476929024.000000, d: 6.936665e-310)
xmm7 0000000000000000 (f: 0.000000, d: 0.000000e+00)
xmm8 0000000000000000 (f: 0.000000, d: 0.000000e+00)
xmm9 0000000000000000 (f: 0.000000, d: 0.000000e+00)
xmm10 0000000000000000 (f: 0.000000, d: 0.000000e+00)
xmm11 0000000000000000 (f: 0.000000, d: 0.000000e+00)
xmm12 0000000000000000 (f: 0.000000, d: 0.000000e+00)
xmm13 0000000000000000 (f: 0.000000, d: 0.000000e+00)
xmm14 0000000000000000 (f: 0.000000, d: 0.000000e+00)
xmm15 0000000000000000 (f: 0.000000, d: 0.000000e+00)
Module=/home/linhu_j9build/openj9-openjdk-jdk19/build/linux-x86_64-server-release/images/jdk/lib/default/libj9gc_full29.so
Module_base_address=00007FB1706E2000
Target=2_90_20221216_000000 (Linux 4.15.0-200-generic)
CPU=amd64 (8 logical CPUs) (0x3ea759000 RAM)
----------- Stack Backtrace -----------
20:00:38.853 0x7fb128003c00    j9mm.141    *   ** ASSERTION FAILED ** at /home/linhu_j9build/openj9-openjdk-jdk19/openj9/runtime/gc_base/ContinuationObjectBuffer.cpp:100: ((false))
JVMDUMP039I Processing dump event "traceassert", detail "" at 2023/01/09 12:00:38 - please wait.
JVMDUMP032I JVM requested System dump using '/root/openj9-openjdk-jdk19/core.20230109.120038.8211.0001.dmp' in response to an event
_ZN27MM_MarkingSchemeRootClearer23scanContinuationObjectsEP18MM_EnvironmentBase+0x136 (0x00007FB170887C96 [libj9gc_full29.so+0x1a5c96])
_ZN14MM_RootScanner13scanClearableEP18MM_EnvironmentBase+0x11b (0x00007FB1707201BB [libj9gc_full29.so+0x3e1bb])
_ZN18MM_MarkingDelegate16workerCompleteGCEP18MM_EnvironmentBase+0x181 (0x00007FB170883DD1 [libj9gc_full29.so+0x1a1dd1])
_ZN19MM_ParallelMarkTask3runEP18MM_EnvironmentBase+0x91 (0x00007FB1708AABA1 [libj9gc_full29.so+0x1c8ba1])
_ZN21MM_ParallelDispatcher16workerEntryPointEP18MM_EnvironmentBase+0x1f7 (0x00007FB1708154D7 [libj9gc_full29.so+0x1334d7])
_Z23dispatcher_thread_proc2P14OMRPortLibraryPv+0x109 (0x00007FB170814D09 [libj9gc_full29.so+0x132d09])
omrsig_protect+0x1e3 (0x00007FB1728EC0A3 [libj9prt29.so+0x2a0a3])
dispatcher_thread_proc+0x3f (0x00007FB17081453F [libj9gc_full29.so+0x13253f])
thread_wrapper+0x162 (0x00007FB1729512B2 [libj9thr29.so+0xf2b2])
start_thread+0xdb (0x00007FB171E0F6DB [libpthread.so.0+0x76db])
clone+0x3f (0x00007FB17256971F [libc.so.6+0x12171f])
---------------------------------------
JVMDUMP039I Processing dump event "gpf", detail "" at 2023/01/09 12:00:38 - please wait.
JVMDUMP010I System dump written to /root/openj9-openjdk-jdk19/core.20230109.120038.8211.0001.dmp
JVMDUMP032I JVM requested Java dump using '/root/openj9-openjdk-jdk19/javacore.20230109.120038.8211.0003.txt' in response to an event
JVMDUMP032I JVM requested System dump using '/root/openj9-openjdk-jdk19/core.20230109.120038.8211.0002.dmp' in response to an event
JVMDUMP010I Java dump written to /root/openj9-openjdk-jdk19/javacore.20230109.120038.8211.0003.txt
JVMDUMP010I System dump written to /root/openj9-openjdk-jdk19/core.20230109.120038.8211.0002.dmp
JVMDUMP032I JVM requested Java dump using '/root/openj9-openjdk-jdk19/javacore.20230109.120038.8211.0005.txt' in response to an event
JVMDUMP032I JVM requested Snap dump using '/root/openj9-openjdk-jdk19/Snap.20230109.120038.8211.0004.trc' in response to an event
JVMDUMP010I Snap dump written to /root/openj9-openjdk-jdk19/Snap.20230109.120038.8211.0004.trc
JVMDUMP013I Processed dump event "traceassert", detail "".
JVMDUMP010I Java dump written to /root/openj9-openjdk-jdk19/javacore.20230109.120038.8211.0005.txt
JVMDUMP032I JVM requested Snap dump using '/root/openj9-openjdk-jdk19/Snap.20230109.120038.8211.0006.trc' in response to an event
dmitripivkine commented 1 year ago

Should be fixed in https://github.com/eclipse-openj9/openj9/pull/16553