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

Can't run execute unit test with `surefire` and IBM Semeru Runtime Open Edition 11.0.13.0 (build 11.0.13+8) #14198

Open TueDissingWork opened 2 years ago

TueDissingWork commented 2 years ago

Java -version output

Output from java -version.

openjdk 11.0.13 2021-10-19
IBM Semeru Runtime Open Edition 11.0.13.0 (build 11.0.13+8)
Eclipse OpenJ9 VM 11.0.13.0 (build openj9-0.29.0, JRE 11 Linux amd64-64-Bit Compressed References 20211022_282 (JIT enabled, AOT enabled)
OpenJ9   - e1e72c497
OMR      - 299b6a2d2
JCL      - 2d83aa3b76 based on jdk-11.0.13+8)

Summary of problem

Trying to execute, otherwise perfectly fine, JUnit tests using the maven-surefire-plugin. When maven tries to fork a couple of JVMs they simply crash. See the below files for additional details. Here's the output of the build:

[INFO]  T E S T S
[INFO] -------------------------------------------------------
[ERROR] 09:50:11.345 0xba00   j9shr.1012   *   ** ASSERTION FAILED ** at ../../../../../openj9/runtime/shared_common/CompositeCache.cpp:1972: ((this->_commonCCInfo->oldWriterCount == _theca->writerCount))
[ERROR] JVMDUMP039I Processing dump event "traceassert", detail "" at 2021/12/23 10:50:11 - please wait.
[ERROR] JVMDUMP032I JVM requested System dump using '/mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/core.20211223.105011.19501.0001.dmp' in response to an event
[ERROR] 09:50:11.353 0xba00   j9shr.1012   *   ** ASSERTION FAILED ** at ../../../../../openj9/runtime/shared_common/CompositeCache.cpp:1972: ((this->_commonCCInfo->oldWriterCount == _theca->writerCount))
[ERROR] JVMDUMP039I Processing dump event "traceassert", detail "" at 2021/12/23 10:50:11 - please wait.
[ERROR] JVMDUMP032I JVM requested System dump using '/mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/core.20211223.105011.19498.0001.dmp' in response to an event
[ERROR] JVMDUMP012E Error in System dump: Error opening "/proc/sys/kernel/core_pattern". Look for core file generated by child process with pid = 19528
[ERROR] JVMDUMP032I JVM requested Java dump using '/mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/javacore.20211223.105011.19501.0002.txt' in response to an event
[ERROR] JVMDUMP012E Error in System dump: Error opening "/proc/sys/kernel/core_pattern". Look for core file generated by child process with pid = 19529
[ERROR] JVMDUMP032I JVM requested Java dump using '/mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/javacore.20211223.105011.19498.0002.txt' in response to an event
[ERROR] JVMDUMP010I Java dump written to /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/javacore.20211223.105011.19501.0002.txt
[ERROR] JVMDUMP032I JVM requested Snap dump using '/mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/Snap.20211223.105011.19501.0003.trc' in response to an event
[ERROR] JVMDUMP010I Java dump written to /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/javacore.20211223.105011.19498.0002.txt
[ERROR] JVMDUMP032I JVM requested Snap dump using '/mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/Snap.20211223.105011.19498.0003.trc' in response to an event
[ERROR] JVMDUMP010I Snap dump written to /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/Snap.20211223.105011.19501.0003.trc
[ERROR] JVMDUMP013I Processed dump event "traceassert", detail "".
[ERROR] JVMDUMP010I Snap dump written to /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/Snap.20211223.105011.19498.0003.trc
[ERROR] JVMDUMP013I Processed dump event "traceassert", detail "".
[INFO]
[INFO] Results:
[INFO]
[INFO] Tests run: 0, Failures: 0, Errors: 0, Skipped: 0
[INFO]
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  6.281 s
[INFO] Finished at: 2021-12-23T10:50:11+01:00
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-surefire-plugin:3.0.0-M5:test (default-test) on project elastic-apm-upgrade-tester: There are test failures.
[ERROR]
[ERROR] Please refer to /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/surefire-reports for the individual test results.
[ERROR] Please refer to dump files (if any exist) [date].dump, [date]-jvmRun[N].dump and [date].dumpstream.
[ERROR] ExecutionException The forked VM terminated without properly saying goodbye. VM crash or System.exit called?
[ERROR] Command was /bin/sh -c cd /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester && /home/tue/.sdkman/candidates/java/11.0.13-sem/bin/java -jar /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/surefire/surefirebooter2522170612268117525.jar /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/surefire 2021-12-23T10-50-09_993-jvmRun1 surefire9680243870299666716tmp surefire_17327662766266562031tmp
[ERROR] Error occurred in starting fork, check output in log
[ERROR] Process Exit Code: 255
[ERROR] ExecutionException The forked VM terminated without properly saying goodbye. VM crash or System.exit called?
[ERROR] Command was /bin/sh -c cd /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester && /home/tue/.sdkman/candidates/java/11.0.13-sem/bin/java -jar /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/surefire/surefirebooter8322593989387672316.jar /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/surefire 2021-12-23T10-50-09_993-jvmRun2 surefire873801014474848685tmp surefire_015531968049463119472tmp
[ERROR] Error occurred in starting fork, check output in log
[ERROR] Process Exit Code: 255
[ERROR] org.apache.maven.surefire.booter.SurefireBooterForkException: ExecutionException The forked VM terminated without properly saying goodbye. VM crash or System.exit called?
[ERROR] Command was /bin/sh -c cd /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester && /home/tue/.sdkman/candidates/java/11.0.13-sem/bin/java -jar /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/surefire/surefirebooter2522170612268117525.jar /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/surefire 2021-12-23T10-50-09_993-jvmRun1 surefire9680243870299666716tmp surefire_17327662766266562031tmp
[ERROR] Error occurred in starting fork, check output in log
[ERROR] Process Exit Code: 255
[ERROR] ExecutionException The forked VM terminated without properly saying goodbye. VM crash or System.exit called?
[ERROR] Command was /bin/sh -c cd /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester && /home/tue/.sdkman/candidates/java/11.0.13-sem/bin/java -jar /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/surefire/surefirebooter8322593989387672316.jar /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/surefire 2021-12-23T10-50-09_993-jvmRun2 surefire873801014474848685tmp surefire_015531968049463119472tmp
[ERROR] Error occurred in starting fork, check output in log
[ERROR] Process Exit Code: 255
[ERROR]         at org.apache.maven.plugin.surefire.booterclient.ForkStarter.awaitResultsDone(ForkStarter.java:532)
[ERROR]         at org.apache.maven.plugin.surefire.booterclient.ForkStarter.runSuitesForkOnceMultiple(ForkStarter.java:405)
[ERROR]         at org.apache.maven.plugin.surefire.booterclient.ForkStarter.run(ForkStarter.java:321)
[ERROR]         at org.apache.maven.plugin.surefire.booterclient.ForkStarter.run(ForkStarter.java:266)
[ERROR]         at org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeProvider(AbstractSurefireMojo.java:1314)
[ERROR]         at org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeAfterPreconditionsChecked(AbstractSurefireMojo.java:1159)
[ERROR]         at org.apache.maven.plugin.surefire.AbstractSurefireMojo.execute(AbstractSurefireMojo.java:932)
[ERROR]         at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:137)
[ERROR]         at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:210)
[ERROR]         at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:156)
[ERROR]         at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:148)
[ERROR]         at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:117)
[ERROR]         at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:81)
[ERROR]         at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:56)
[ERROR]         at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:128)
[ERROR]         at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:305)
[ERROR]         at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:192)
[ERROR]         at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:105)
[ERROR]         at org.apache.maven.cli.MavenCli.execute(MavenCli.java:956)
[ERROR]         at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:288)
[ERROR]         at org.apache.maven.cli.MavenCli.main(MavenCli.java:192)
[ERROR]         at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[ERROR]         at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[ERROR]         at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[ERROR]         at java.base/java.lang.reflect.Method.invoke(Method.java:566)
[ERROR]         at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:289)
[ERROR]         at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:229)
[ERROR]         at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:415)
[ERROR]         at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:356)
[ERROR] Caused by: org.apache.maven.surefire.booter.SurefireBooterForkException: The forked VM terminated without properly saying goodbye. VM crash or System.exit called?
[ERROR] Command was /bin/sh -c cd /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester && /home/tue/.sdkman/candidates/java/11.0.13-sem/bin/java -jar /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/surefire/surefirebooter8322593989387672316.jar /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/surefire 2021-12-23T10-50-09_993-jvmRun2 surefire873801014474848685tmp surefire_015531968049463119472tmp
[ERROR] Error occurred in starting fork, check output in log
[ERROR] Process Exit Code: 255
[ERROR]         at org.apache.maven.plugin.surefire.booterclient.ForkStarter.fork(ForkStarter.java:748)
[ERROR]         at org.apache.maven.plugin.surefire.booterclient.ForkStarter.access$700(ForkStarter.java:121)
[ERROR]         at org.apache.maven.plugin.surefire.booterclient.ForkStarter$1.call(ForkStarter.java:393)
[ERROR]         at org.apache.maven.plugin.surefire.booterclient.ForkStarter$1.call(ForkStarter.java:370)
[ERROR]         at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
[ERROR]         at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
[ERROR]         at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
[ERROR]         at java.base/java.lang.Thread.run(Thread.java:866)
[ERROR]
[ERROR] -> [Help 1]
[ERROR]
[ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch.
[ERROR] Re-run Maven using the -X switch to enable full debug logging.
[ERROR]
[ERROR] For more information about the errors and possible solutions, please read the following articles:
[ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/MojoExecutionException

Diagnostic files

I have added the resulting Snap and javacore files. javacore.20211223.105011.19498.0002.txt javacore.20211223.105011.19501.0002.txt

Had to add .txtto the Snap files in order to being able to upload them, but here they are: Snap.20211223.105011.19498.0003.trc.txt Snap.20211223.105011.19501.0003.trc.txt

pshipton commented 2 years ago

@hangshao0 fyi

You can work around it by disabling the shared cache. Either via -Xshareclasses:none on the java command line, or set the environment variable OPENJ9_JAVA_OPTIONS=-Xshareclasses:none.

TueDissingWork commented 2 years ago

@hangshao0 fyi

You can work around it by disabling the shared cache. Either via -Xshareclasses:none on the java command line, or set the environment variable OPENJ9_JAVA_OPTIONS=-Xshareclasses:none.

Seems to work great. Thank!

hangshao0 commented 2 years ago

When maven tries to fork a couple of JVMs they simply crash. See the below files for additional details.

Does it happen frequently ? I want to know how reproducible it is (I don't recall we fail at this assertion before).

TueDissingWork commented 2 years ago

When maven tries to fork a couple of JVMs they simply crash. See the below files for additional details.

Does it happen frequently ? I want to know how reproducible it is (I don't recall we fail at this assertion before).

It seems to happen for every tests. So as soon as the JVM is forked (or at least tried to) this happens.

hangshao0 commented 2 years ago

There is only one place changing _commonCCInfo->oldWriterCount, that is SH_CompositeCacheImpl::enterWriteMutex(). _theca->writerCount can only be changed inside SH_CompositeCacheImpl::enterWriteMutex() and SH_CompositeCacheImpl::exitWriteMutex(). Those changes are all protected by the write lock. It is still not clear to me how this could happen.

I had no luck reproducing this locally.

@TueDissingWork, do you still have the shared cache file /home/tue/javasharedresources/C290M11F1A64P_sharedcc_tue_G41L00 and the system core file /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/core.20211223.105011.19501.0001.dmp ? Need to look at them for more information. It is even better if you have a test case (and instructions) that I can use to reproduce it.

If you run java -Xshareclasses:destroyAll to do a cleanup before executing the unit test, does it still fail ?

TueDissingWork commented 2 years ago

I only have the cache file. C290M11F1A64P_sharedcc_tue_G41L00.zip.

It still happens when I execute a simple unit test execution from Maven. Here's the latest dumps: jvm dump files.zip.

Running java -Xshareclasses:destroyAll -Xnocompressedrefs as suggested. The mvn test execution results in the same error:

[ERROR] Caused by: org.apache.maven.surefire.booter.SurefireBooterForkException: The forked VM terminated without properly saying goodbye. VM crash or System.exit called?
[ERROR] Command was /bin/sh -c cd /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester && /home/tue/.sdkman/candidates/java/11.0.13-sem/bin/java -javaagent:/home/tue/.m2/repository/org/jacoco/org.jacoco.agent/0.8.7/org.jacoco.agent-0.8.7-runtime.jar=destfile=/mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/jacoco.exec -jar /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/surefire/surefirebooter13345449562026248972.jar /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/surefire 2022-01-31T10-01-29_646-jvmRun2 surefire12412844581550621023tmp surefire_110027723266207190383tmp
[ERROR] Error occurred in starting fork, check output in log
[ERROR] Process Exit Code: 255
[ERROR]         at org.apache.maven.plugin.surefire.booterclient.ForkStarter.fork(ForkStarter.java:748)
[ERROR]         at org.apache.maven.plugin.surefire.booterclient.ForkStarter.access$700(ForkStarter.java:121)
[ERROR]         at org.apache.maven.plugin.surefire.booterclient.ForkStarter$1.call(ForkStarter.java:393)
[ERROR]         at org.apache.maven.plugin.surefire.booterclient.ForkStarter$1.call(ForkStarter.java:370)
[ERROR]         at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
[ERROR]         at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
[ERROR]         at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
[ERROR]         at java.base/java.lang.Thread.run(Thread.java:866)

java dump files - mvn test.zip

hangshao0 commented 2 years ago

Looking at the trace history, JVM1:

3XEHSTTYPE     09:50:11:353690000 GMT j9shr.1012 - * ** ASSERTION FAILED ** at ../../../../../openj9/runtime/shared_common/CompositeCache.cpp:1972: ((this->_commonCCInfo->oldWriterCount == _theca->writerCount))
3XEHSTTYPE     09:50:11:353682000 GMT j9shr.2334 - * CC changePartialPageProtection: Returning without changing page protection for address 00007FC2ABEF8BF4 to read-only
3XEHSTTYPE     09:50:11:353681000 GMT j9shr.2334 - * CC changePartialPageProtection: Returning without changing page protection for address 00007FC2ABB90828 to read-only
3XEHSTTYPE     09:50:11:353681000 GMT j9shr.2334 - * CC changePartialPageProtection: Returning without changing page protection for address 00007FC2AAD8BE3C to read-only
3XEHSTTYPE     09:50:11:353678000 GMT j9shr.2334 - * CC changePartialPageProtection: Returning without changing page protection for address 00007FC2A89CCC20 to read-only
3XEHSTTYPE     09:50:11:340972000 GMT j9shr.643 -  <M startup: Manager started successfully
3XEHSTTYPE     09:50:11:340972000 GMT j9shr.636 -  <M initializeHashTable: Exiting with 0
...
...
3XEHSTTYPE     09:50:11:338271000 GMT j9shr.683 -  >BDMI localHashTableCreate: Creating new hashtable with 691 initial entries
3XEHSTTYPE     09:50:11:338270000 GMT j9shr.635 -  >M initializeHashTable: Entering for Manager of TYPE_BYTE_DATA
3XEHSTTYPE     09:50:11:338269000 GMT j9shr.639 -  >M startup: Starting up Manager of TYPE_BYTE_DATA
3XEHSTTYPE     09:50:11:338263000 GMT j9shr.643 -  <M startup: Manager started successfully
3XEHSTTYPE     09:50:11:338263000 GMT j9shr.636 -  <M initializeHashTable: Exiting with 0
3XEHSTTYPE     09:50:11:338262000 GMT j9shr.590 -  <SMI localHashTableCreate: Created hashtable at address 0x00007FC2EC152280
3XEHSTTYPE     09:50:11:338211000 GMT j9shr.589 -  >SMI localHashTableCreate: Creating new hashtable with 691 initial entries
3XEHSTTYPE     09:50:11:338211000 GMT j9shr.635 -  >M initializeHashTable: Entering for Manager of TYPE_SCOPE
3XEHSTTYPE     09:50:11:338208000 GMT j9shr.639 -  >M startup: Starting up Manager of TYPE_SCOPE

JVM2:

3XEHSTTYPE     09:50:11:344798403 GMT j9shr.1012 - * ** ASSERTION FAILED ** at ../../../../../openj9/runtime/shared_common/CompositeCache.cpp:1972: ((this->_commonCCInfo->oldWriterCount == _theca->writerCount))
3XEHSTTYPE     09:50:11:344796407 GMT j9shr.2334 - * CC changePartialPageProtection: Returning without changing page protection for address 00007F890FEF8BF4 to read-only
3XEHSTTYPE     09:50:11:344796407 GMT j9shr.2334 - * CC changePartialPageProtection: Returning without changing page protection for address 00007F890FB90828 to read-only
3XEHSTTYPE     09:50:11:344795409 GMT j9shr.2334 - * CC changePartialPageProtection: Returning without changing page protection for address 00007F890ED8BE3C to read-only
3XEHSTTYPE     09:50:11:344794411 GMT j9shr.2334 - * CC changePartialPageProtection: Returning without changing page protection for address 00007F890C9CCC20 to read-only
3XEHSTTYPE     09:50:11:332472055 GMT j9shr.643 -  <M startup: Manager started successfully
3XEHSTTYPE     09:50:11:332471057 GMT j9shr.636 -  <M initializeHashTable: Exiting with 0
3XEHSTTYPE     09:50:11:332470059 GMT j9shr.563 -  <RRM localHashTableCreate: Created hashtable at address 0x00007F895019D890
3XEHSTTYPE     09:50:11:331889221 GMT j9shr.562 -  >RRM localHashTableCreate: Creating new hashtable with 13521 initial entries
...
...
3XEHSTTYPE     09:50:11:329714570 GMT j9shr.635 -  >M initializeHashTable: Entering for Manager of TYPE_BYTE_DATA
3XEHSTTYPE     09:50:11:329714570 GMT j9shr.639 -  >M startup: Starting up Manager of TYPE_BYTE_DATA
3XEHSTTYPE     09:50:11:329708582 GMT j9shr.643 -  <M startup: Manager started successfully
3XEHSTTYPE     09:50:11:329707584 GMT j9shr.636 -  <M initializeHashTable: Exiting with 0
3XEHSTTYPE     09:50:11:329707584 GMT j9shr.590 -  <SMI localHashTableCreate: Created hashtable at address 0x00007F8950152280
3XEHSTTYPE     09:50:11:329658682 GMT j9shr.589 -  >SMI localHashTableCreate: Creating new hashtable with 691 initial entries
3XEHSTTYPE     09:50:11:329658682 GMT j9shr.635 -  >M initializeHashTable: Entering for Manager of TYPE_SCOPE
3XEHSTTYPE     09:50:11:329656686 GMT j9shr.639 -  >M startup: Starting up Manager of TYPE_SCOPE

The first item in the cache is SCOPE !j9utf8 0x00007F46EFAE8FEC J9AOTHeader. They both failed when exiting the write lock after reading the cache. The code is:

https://github.com/eclipse-openj9/openj9/blob/0d09d580887e406a434ecf2a195c6c1a64cc72c8/runtime/shared_common/CacheMap.cpp#L673-L689

If the timestamps of the trace points are correct, JVM1 should have the write lock between 09:50:11:338208000 to 09:50:11:353690000. JVM2 should have the write lock between 09:50:11:329656686 to 09:50:11:344798403. There is an overlap between these 2, which means the write lock did not give us exclusive access (at least on that machine). This explained why both JVMs failed at assertion at CompositeCache.cpp:1972. The writer count has been changed by the other JVM.

hangshao0 commented 2 years ago

We use OMR API omrfile_lock_bytes() which calls fcntl() for file lock. @TueDissingWork Can you please try with option -Xtrace:maximal={omrport.246-254,j9shr.744-749} (you can set it in OPENJ9_JAVA_OPTIONS) to capture more trace info in the dump files, so that we can see if correct values are passed to these APIs.

pshipton commented 2 years ago

What type of file system does the shared cache reside on? We know file locking doesn't work on NFS and the JVM detects when the cache would be on this file system and fails to enable the shared cache, which also fails to start the JVM unless running with nonfatal.

JVMSHRC287E Persistent cache cannot be located on a networked file system. Either select "nonpersistent" or a different cacheDir.
JVMSHRC840E Failed to start up the shared cache.
hangshao0 commented 2 years ago

What type of file system does the shared cache reside on?

/home/tue/javasharedresources/ is being used. So the question is what kind of file system is /home/tue/javasharedresources/. We discourage use of network/mounted/shared drive.

TueDissingWork commented 2 years ago

Sure I can add more details. Will run the test shortly. I am running this on a Windows 10 host inside WSL1.

TueDissingWork commented 2 years ago

The mvn test run exits with this error:

WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by com.google.inject.internal.cglib.core.$ReflectUtils$1 (file:/usr/share/maven/lib/guice.jar) to method java.lang.ClassLoader.defineClass(java.lang.String,byte[],int,int,java.security.ProtectionDomain)
WARNING: Please consider reporting this to the maintainers of com.google.inject.internal.cglib.core.$ReflectUtils$1
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
[INFO] Scanning for projects...
Downloading from central: https://artifactory.ccta.dk/libs-snapshot/dk/ufst/devops/maven/spring-boot-project/$%7Brevision%7D$%7Bsha1%7D$%7Bchangelist%7D/spring-boot-project-$%7Brevision%7D$%7Bsha1%7D$%7Bchangelist%7D.pom
Downloading from devops-maven-virtual: https://artifactory.ccta.dk/devops-maven-virtual/dk/ufst/devops/maven/spring-boot-project/$%7Brevision%7D$%7Bsha1%7D$%7Bchangelist%7D/spring-boot-project-$%7Brevision%7D$%7Bsha1%7D$%7Bchangelist%7D.pom
Downloading from billetautomat-maven-local: https://artifactory.ccta.dk/billetautomat-maven-local/dk/ufst/devops/maven/spring-boot-project/$%7Brevision%7D$%7Bsha1%7D$%7Bchangelist%7D/spring-boot-project-$%7Brevision%7D$%7Bsha1%7D$%7Bchangelist%7D.pom
Downloading from archetype: https://artifactory.ccta.dk/devops-maven-local/dk/ufst/devops/maven/spring-boot-project/$%7Brevision%7D$%7Bsha1%7D$%7Bchangelist%7D/spring-boot-project-$%7Brevision%7D$%7Bsha1%7D$%7Bchangelist%7D.pom
[WARNING] Failed to build parent project for dk.ufst.test:elastic-apm-upgrade-tester:jar:0.1-SNAPSHOT
[WARNING]
[WARNING] Some problems were encountered while building the effective model for dk.ufst.test:elastic-apm-upgrade-tester:jar:0.1-SNAPSHOT
[WARNING] 'build.pluginManagement.plugins.plugin.(groupId:artifactId)' must be unique but found duplicate declaration of plugin org.codehaus.mojo:exec-maven-plugin @ dk.ufst.devops.maven:maven-super-pom:${revision}${sha1}${changelist}, /home/tue/.m2/repository/dk/ufst/devops/maven/maven-super-pom/0.3.6/maven-super-pom-0.3.6.pom, line 239, column 25
[WARNING]
[WARNING] It is highly recommended to fix these problems because they threaten the stability of your build.
[WARNING]
[WARNING] For this reason, future Maven versions might no longer support building such malformed projects.
[WARNING]
[INFO]
[INFO] --------------< dk.ufst.test:elastic-apm-upgrade-tester >---------------
[INFO] Building elastic-apm-upgrade-tester 0.1-SNAPSHOT
[INFO] --------------------------------[ jar ]---------------------------------
[INFO]
[INFO] --- yaml-properties-maven-plugin:1.1.3:read-project-properties (default) @ elastic-apm-upgrade-tester ---
[INFO]
[INFO] --- jacoco-maven-plugin:0.8.7:prepare-agent (default-prepare-agent) @ elastic-apm-upgrade-tester ---
[INFO] argLine set to -javaagent:/home/tue/.m2/repository/org/jacoco/org.jacoco.agent/0.8.7/org.jacoco.agent-0.8.7-runtime.jar=destfile=/mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/jacoco.exec
[INFO]
[INFO] --- git-changelog-maven-plugin:1.78:git-changelog (GenerateGitChangelog) @ elastic-apm-upgrade-tester ---
[INFO] Skipping changelog generation
[INFO]
[INFO] --- git-changelog-maven-plugin:1.78:git-changelog (GenerateGitChangelogHtml) @ elastic-apm-upgrade-tester ---
[INFO] Skipping changelog generation
[INFO]
[INFO] --- git-changelog-maven-plugin:1.78:git-changelog (GenerateGitReleasenotes) @ elastic-apm-upgrade-tester ---
[INFO] Skipping changelog generation
[INFO]
[INFO] --- git-changelog-maven-plugin:1.78:git-changelog (GenerateGitReleasenotesSpecificVersion) @ elastic-apm-upgrade-tester ---
[INFO] Skipping changelog generation
[INFO]
[INFO] --- maven-resources-plugin:2.6:resources (default-resources) @ elastic-apm-upgrade-tester ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] Copying 1 resource
[INFO] Copying 2 resources
[INFO]
[INFO] --- maven-compiler-plugin:3.1:compile (default-compile) @ elastic-apm-upgrade-tester ---
[INFO] Nothing to compile - all classes are up to date
[INFO]
[INFO] --- maven-resources-plugin:2.6:testResources (default-testResources) @ elastic-apm-upgrade-tester ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] skip non existing resourceDirectory /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/src/test/resources
[INFO]
[INFO] --- maven-compiler-plugin:3.1:testCompile (default-testCompile) @ elastic-apm-upgrade-tester ---
[INFO] Nothing to compile - all classes are up to date
[INFO]
[INFO] --- maven-surefire-plugin:3.0.0-M5:test (default-test) @ elastic-apm-upgrade-tester ---
[INFO]
[INFO] -------------------------------------------------------
[INFO]  T E S T S
[INFO] -------------------------------------------------------
[ERROR] 09:52:40.955 0xba00   j9shr.1012   *   ** ASSERTION FAILED ** at ../../../../../openj9/runtime/shared_common/CompositeCache.cpp:1972: ((this->_commonCCInfo->oldWriterCount == _theca->writerCount))
[ERROR] JVMDUMP039I Processing dump event "traceassert", detail "" at 2022/02/01 10:52:40 - please wait.
[ERROR] 09:52:40.961 0xba00   j9shr.1012   *   ** ASSERTION FAILED ** at ../../../../../openj9/runtime/shared_common/CompositeCache.cpp:1972: ((this->_commonCCInfo->oldWriterCount == _theca->writerCount))
[ERROR] JVMDUMP032I JVM requested System dump using '/mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/core.20220201.105240.17058.0001.dmp' in response to an event
[ERROR] JVMDUMP039I Processing dump event "traceassert", detail "" at 2022/02/01 10:52:40 - please wait.
[ERROR] JVMDUMP032I JVM requested System dump using '/mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/core.20220201.105240.17059.0001.dmp' in response to an event
[ERROR] JVMDUMP012E Error in System dump: Error opening "/proc/sys/kernel/core_pattern". Look for core file generated by child process with pid = 17088
[ERROR] JVMDUMP032I JVM requested Java dump using '/mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/javacore.20220201.105240.17058.0002.txt' in response to an event
[ERROR] JVMDUMP012E Error in System dump: Error opening "/proc/sys/kernel/core_pattern". Look for core file generated by child process with pid = 17089
[ERROR] JVMDUMP032I JVM requested Java dump using '/mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/javacore.20220201.105240.17059.0002.txt' in response to an event
[ERROR] JVMDUMP010I Java dump written to /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/javacore.20220201.105240.17058.0002.txt
[ERROR] JVMDUMP010I Java dump written to /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/javacore.20220201.105240.17059.0002.txt
[ERROR] JVMDUMP032I JVM requested Snap dump using '/mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/Snap.20220201.105240.17058.0003.trc' in response to an event
[ERROR] JVMDUMP032I JVM requested Snap dump using '/mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/Snap.20220201.105240.17059.0003.trc' in response to an event
[ERROR] JVMDUMP010I Snap dump written to /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/Snap.20220201.105240.17059.0003.trc
[ERROR] JVMDUMP013I Processed dump event "traceassert", detail "".
[ERROR] JVMDUMP010I Snap dump written to /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/Snap.20220201.105240.17058.0003.trc
[ERROR] JVMDUMP013I Processed dump event "traceassert", detail "".
[INFO]
[INFO] Results:
[INFO]
[INFO] Tests run: 0, Failures: 0, Errors: 0, Skipped: 0
[INFO]
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  8.203 s
[INFO] Finished at: 2022-02-01T10:52:41+01:00
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-surefire-plugin:3.0.0-M5:test (default-test) on project elastic-apm-upgrade-tester: There are test failures.
[ERROR]
[ERROR] Please refer to /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/surefire-reports for the individual test results.
[ERROR] Please refer to dump files (if any exist) [date].dump, [date]-jvmRun[N].dump and [date].dumpstream.
[ERROR] ExecutionException The forked VM terminated without properly saying goodbye. VM crash or System.exit called?
[ERROR] Command was /bin/sh -c cd /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester && /home/tue/.sdkman/candidates/java/11.0.13-sem/bin/java -javaagent:/home/tue/.m2/repository/org/jacoco/org.jacoco.agent/0.8.7/org.jacoco.agent-0.8.7-runtime.jar=destfile=/mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/jacoco.exec -jar /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/surefire/surefirebooter10113877977383044292.jar /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/surefire 2022-02-01T10-52-39_328-jvmRun1 surefire13618027866058611471tmp surefire_015021474189092031813tmp
[ERROR] Error occurred in starting fork, check output in log
[ERROR] Process Exit Code: 255
[ERROR] ExecutionException The forked VM terminated without properly saying goodbye. VM crash or System.exit called?
[ERROR] Command was /bin/sh -c cd /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester && /home/tue/.sdkman/candidates/java/11.0.13-sem/bin/java -javaagent:/home/tue/.m2/repository/org/jacoco/org.jacoco.agent/0.8.7/org.jacoco.agent-0.8.7-runtime.jar=destfile=/mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/jacoco.exec -jar /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/surefire/surefirebooter12877429551130174230.jar /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/surefire 2022-02-01T10-52-39_328-jvmRun2 surefire6955513382444848432tmp surefire_111929949751632039425tmp
[ERROR] Error occurred in starting fork, check output in log
[ERROR] Process Exit Code: 255
[ERROR] org.apache.maven.surefire.booter.SurefireBooterForkException: ExecutionException The forked VM terminated without properly saying goodbye. VM crash or System.exit called?
[ERROR] Command was /bin/sh -c cd /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester && /home/tue/.sdkman/candidates/java/11.0.13-sem/bin/java -javaagent:/home/tue/.m2/repository/org/jacoco/org.jacoco.agent/0.8.7/org.jacoco.agent-0.8.7-runtime.jar=destfile=/mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/jacoco.exec -jar /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/surefire/surefirebooter10113877977383044292.jar /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/surefire 2022-02-01T10-52-39_328-jvmRun1 surefire13618027866058611471tmp surefire_015021474189092031813tmp
[ERROR] Error occurred in starting fork, check output in log
[ERROR] Process Exit Code: 255
[ERROR] ExecutionException The forked VM terminated without properly saying goodbye. VM crash or System.exit called?
[ERROR] Command was /bin/sh -c cd /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester && /home/tue/.sdkman/candidates/java/11.0.13-sem/bin/java -javaagent:/home/tue/.m2/repository/org/jacoco/org.jacoco.agent/0.8.7/org.jacoco.agent-0.8.7-runtime.jar=destfile=/mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/jacoco.exec -jar /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/surefire/surefirebooter12877429551130174230.jar /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/surefire 2022-02-01T10-52-39_328-jvmRun2 surefire6955513382444848432tmp surefire_111929949751632039425tmp
[ERROR] Error occurred in starting fork, check output in log
[ERROR] Process Exit Code: 255
[ERROR]         at org.apache.maven.plugin.surefire.booterclient.ForkStarter.awaitResultsDone(ForkStarter.java:532)
[ERROR]         at org.apache.maven.plugin.surefire.booterclient.ForkStarter.runSuitesForkOnceMultiple(ForkStarter.java:405)
[ERROR]         at org.apache.maven.plugin.surefire.booterclient.ForkStarter.run(ForkStarter.java:321)
[ERROR]         at org.apache.maven.plugin.surefire.booterclient.ForkStarter.run(ForkStarter.java:266)
[ERROR]         at org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeProvider(AbstractSurefireMojo.java:1314)
[ERROR]         at org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeAfterPreconditionsChecked(AbstractSurefireMojo.java:1159)
[ERROR]         at org.apache.maven.plugin.surefire.AbstractSurefireMojo.execute(AbstractSurefireMojo.java:932)
[ERROR]         at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:137)
[ERROR]         at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:210)
[ERROR]         at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:156)
[ERROR]         at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:148)
[ERROR]         at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:117)
[ERROR]         at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:81)
[ERROR]         at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:56)
[ERROR]         at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:128)
[ERROR]         at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:305)
[ERROR]         at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:192)
[ERROR]         at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:105)
[ERROR]         at org.apache.maven.cli.MavenCli.execute(MavenCli.java:956)
[ERROR]         at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:288)
[ERROR]         at org.apache.maven.cli.MavenCli.main(MavenCli.java:192)
[ERROR]         at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[ERROR]         at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[ERROR]         at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[ERROR]         at java.base/java.lang.reflect.Method.invoke(Method.java:566)
[ERROR]         at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:289)
[ERROR]         at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:229)
[ERROR]         at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:415)
[ERROR]         at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:356)
[ERROR] Caused by: org.apache.maven.surefire.booter.SurefireBooterForkException: The forked VM terminated without properly saying goodbye. VM crash or System.exit called?
[ERROR] Command was /bin/sh -c cd /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester && /home/tue/.sdkman/candidates/java/11.0.13-sem/bin/java -javaagent:/home/tue/.m2/repository/org/jacoco/org.jacoco.agent/0.8.7/org.jacoco.agent-0.8.7-runtime.jar=destfile=/mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/jacoco.exec -jar /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/surefire/surefirebooter12877429551130174230.jar /mnt/c/Users/w27214/code/demo/elastic-apm-upgrade-tester/target/surefire 2022-02-01T10-52-39_328-jvmRun2 surefire6955513382444848432tmp surefire_111929949751632039425tmp
[ERROR] Error occurred in starting fork, check output in log
[ERROR] Process Exit Code: 255
[ERROR]         at org.apache.maven.plugin.surefire.booterclient.ForkStarter.fork(ForkStarter.java:748)
[ERROR]         at org.apache.maven.plugin.surefire.booterclient.ForkStarter.access$700(ForkStarter.java:121)
[ERROR]         at org.apache.maven.plugin.surefire.booterclient.ForkStarter$1.call(ForkStarter.java:393)
[ERROR]         at org.apache.maven.plugin.surefire.booterclient.ForkStarter$1.call(ForkStarter.java:370)
[ERROR]         at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
[ERROR]         at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
[ERROR]         at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
[ERROR]         at java.base/java.lang.Thread.run(Thread.java:866)
[ERROR]
[ERROR] -> [Help 1]
[ERROR]
[ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch.
[ERROR] Re-run Maven using the -X switch to enable full debug logging.
[ERROR]
[ERROR] For more information about the errors and possible solutions, please read the following articles:
[ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/MojoExecutionException

Here's the associated dump files: java-trace-maximal.zip

pshipton commented 2 years ago

I am running this on a Windows 10 host inside WSL1.

This is not a supported platform.