Requesting information for diagnosing fatal error with JVMCI

[michaeljohnalbers]

In one of our apps we're seeing frequent fatal errors coming from the JVM. They mostly look like this

#
# If you would like to submit a bug report, please visit:
# https://github.com/oracle/graal/issues
#
#
# V [libjvm.so+0x972032] JVMCIRuntime::init_shared_library_javavm()+0x282
# Core dump will be written. Default location: /app/core.1
#
# An error report file with more information is saved as:
# /tmp/hs_err_pid1.log
#
# A fatal error has been detected by the Java Runtime Environment:
#
# Internal Error (jvmciRuntime.cpp:1255), pid=1, tid=32
# fatal error: JNI_CreateJavaVM failed with return value -4
#
# JRE version: OpenJDK Runtime Environment GraalVM CE 22.3.1 (17.0.6+10) (build 17.0.6+10-jvmci-22.3-b13)
# Java VM: OpenJDK 64-Bit Server VM GraalVM CE 22.3.1 (17.0.6+10-jvmci-22.3-b13, mixed mode, sharing, tiered, jvmci, jvmci compiler, compressed oops, compressed class ptrs, g1 gc, linux-amd64)
# Problematic frame:

Unfortunately we don't have access to the core file or hs_err_pid file as we're running the app in a Docker container within AWS ECS.

These crashes are happening after our app has been running for quite a while, in many cases several hours. We've tried a few different things to stop these, but none have worked (increasing the JVM heap size, reducing the number of Context objects we have instantiated, attempting to lower the overall memory footprint of the process). Our ECS instances appear to have quite a bit of free memory (20+GB) when these crashes happen and the network and CPU load is not overwhelming either.

Our app is a Java web-based app using Dropwizard. We also are using DuckDB as an in-memory database which is accessed via JNI calls. And, we're using GraalVM specifically for the polyglot capabilities, namely the ability to run some custom Javascript.

In order to help determine the cause of this we're hoping that you can provide any information about why these specific error may be happening.

Additionally, if you could provide answers to the following questions we would greatly appreciate it.

1. Is the "-4" error code the same as JNI_ENOMEM? If so, is this function trying to use JVM heap memory or off-heap memory?
2. I've dug into the jdk code where this is happening just a little bit and I'm curious why it appears that the JVM is attempting to load a shared library after hours of running? (Or am I misunderstanding what is happening?)
3. Sometimes we get an error code of -1000000009, what does that indicate?

Thank you for any help you can provide.

[tkrodriguez]

This failure is from the creation of a new isolate for compilation by the JIT so the error message means we couldn't allocate the storage required for a new isolate. Graal is packaged into a shared library in this configuration. The error code suggests that there isn't enough memory available but it's hard to know since we just get the error code without any details. Can you get an hs_err for us? That would give us a clearer sense of the state of memory. To work around this you can delay shutdown of idle isolates indefinitely using -XX:JVMCICompilerIdleDelay=2147483647.

As far as the -1000000009 error code, if we really are short on memory then something else might have gone wrong with allocation in HotSpot leading to that code.

[dougxc]

To add to Tom's info, here's where the -4 (i.e. JNI_ENOMEM) is most likely coming from:

graal/substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/jni/functions/JNIInvocationInterface.java

Line 178 in ce711ba

} else if (code == CEntryPointErrors.MAP_HEAP_FAILED || code == CEntryPointErrors.RESERVE_ADDRESS_SPACE_FAILED || code == CEntryPointErrors.INSUFFICIENT_ADDRESS_SPACE) {

Which in turn is most likely coming from here:

graal/substratevm/src/com.oracle.svm.core.posix/src/com/oracle/svm/core/posix/linux/LinuxImageHeapProvider.java

Line 229 in ce711ba

return CEntryPointErrors.MAP_HEAP_FAILED;

As Tom states, having the hs-err file would help diagnose further.

[dougxc]

In the mean time, I have opened https://bugs.openjdk.org/browse/JDK-8305932 to try to avoid crashing in such scenarios.

[michaeljohnalbers]

@tkrodriguez Thanks for your response. I tried adding the -XX:JVMCICompilerIdleDelay=2147483647 option to our command line arguments but it doesn't appear to have helped the situation.

It took a while but I was able to grab something of an hs_err log file which I've attached. I think it is probably corrupted as I had to pull it out of AWS Cloudwatch (which is remarkably unhelpful) as we're running our code in AWS ECS (I used -XX:ErrorFile=/dev/stdout). If you need me to find a way to get a better file, I can look into that.
prod-flamingo-logs-04202023-sorted.txt

[michaeljohnalbers]

Here's a better hs_err file.
hs_err_1_b59eee8482444ab088cb0e6e1c69ed13.log

[dougxc]

Thanks @michaeljohnalbers . That looks like a crash in the SVM garbage collector:

C  [libjvmcicompiler.so+0x23cc7f]  FunctionPointerLogHandler_fatalError_0d7d19dd11c15e8ad2801390c27849a49ca7265e+0x5f
C  [libjvmcicompiler.so+0x2048e2]  VMErrorSubstitutions_doShutdown_aeb5d1d3ebe598065e66ebaae797f91d1329fa3a+0x2b2
C  [libjvmcicompiler.so+0x2049a4]  VMErrorSubstitutions_shouldNotReachHere_13fde24ffffa6b874d2a63db3d8b396e9bdad387+0x54
C  [libjvmcicompiler.so+0x283148]  VMError_shouldNotReachHere_82bb6c3846800547f6b2ca3f57605624cf663789+0x18
C  [libjvmcicompiler.so+0x1ce864]  GCImpl$CollectionVMOperation_operate_e7bc4bc722e6e57168cde3dda82b827c444f664f+0x54
C  [libjvmcicompiler.so+0x27ce31]  VMOperation_execute_0f39afa5ac0d6a859fd5b10ec44a5f01176570b3+0xf1
C  [libjvmcicompiler.so+0x27d917]  VMOperationControl$WorkQueues_drain_fc251cfc5f5ad2ffe0a4c5f439a2f84dcde8481c+0x67
C  [libjvmcicompiler.so+0x27e037]  VMOperationControl$WorkQueues_executeAllQueuedVMOperations_25b2bf3190fe2a774058bff8d39933d94865ff3c+0x157
C  [libjvmcicompiler.so+0x27de54]  VMOperationControl$WorkQueues_enqueueAndExecute_607383fb6e6bc84e65ff317d4677ca194ec5dadb+0x64
C  [libjvmcicompiler.so+0x27e499]  VMOperationControl_enqueue_be44b5ab78dc5a87fceed9be4839fa5eb84b0b2a+0xb9
C  [libjvmcicompiler.so+0x2771e8]  NativeVMOperation_enqueue_8e9693900fe03773a622f8bdf4cb56b579d8dbd2+0x38
C  [libjvmcicompiler.so+0x1cf588]  GCImpl_collectWithoutAllocating_a9c1c4d555d68ece8c1e7086d3ebd4046d549b12+0x108
C  [libjvmcicompiler.so+0x1cfdd1]  GCImpl_maybeCollectOnAllocation_a8740e3dd9280e81527189388e1afd01a514ab52+0x71

cc @christianhaeubl

It would help to also get the libgraal specific crash file. This would normally be the hs_err_pid<nnn>_libjvmci.log file next to hs_err_pid<nnn>.log file. However, you can specify its location explicitly with the (JVMCINativeLibraryErrorFile option](https://github.com/graalvm/labs-openjdk-17/blob/7eea82d922362c15c03242e1f39d49079e467ff3/src/hotspot/share/jvmci/jvmci_globals.hpp#L150-L153):

-XX:JVMCINativeLibraryErrorFile=/efs/flamingo/errorFiles/b59eee8482444ab088cb0e6e1c69ed13/hs_err_%p_libjvmci.log

[dougxc]

@christianhaeubl what other -Dlibgraal.* flags (e.g. -Dlibgraal.PrintGC=true?) would you recommend to help diagnose an SVM GC issue?

[christianhaeubl]

This indeed looks like a crash in the SVM GC. For diagnosing, we would need the hs_err_pid<nnn>_libjvmci.log file as @dougxc mentioned. I don't think that there is any need for extra flags at the moment because the hs_err_pid<nnn>_libjvmci.log file should contain the most relevant information by default.

[michaeljohnalbers]

@dougxc @christianhaeubl Here's some new crash files.

hs_err_pid1_libjvmci_de131324db024af9a2edcbce32588880.log
hs_err_1_de131324db024af9a2edcbce32588880.log
hs_err_pid1_libjvmci_2eab7644b37247cabf3f45a58868b385.log
hs_err_1_2eab7644b37247cabf3f45a58868b385.log

These look like the VM just ran out of memory. I haven't seen any other crashes from other errors. If that happens I'll add the files at that point.

[christianhaeubl]

Thanks for the crash logs.
Based on the libjvmci logs, it seems that the Native Image GC tries to allocate a 1 MB chunk of memory but the operating system denies the request. This seems to happen pretty pretty randomly, after 100 - 1000 successful GCs. This problem happens for multiple compilation isolates at pretty much the same time (within 100 ms). Based on the HotSpot log, there is plenty of RAM available after the crash (it is possible that memory was freed in the meanwhile).

@michaeljohnalbers : is there anything running on the machine that can cause large spikes in memory usage so that the operating system has a reason to deny the allocation?

[michaeljohnalbers]

There definitely is. We're using DuckDB in our Java processes. We load customer data into this database. We use a fairly simple method for loading the data and we have seen many times where we'll get a particularly large dataset assigned to an already loaded up machine.

I'm still waiting to see a crash due to the initial problem I described above, which wasn't a failed allocation (or at least not like the two in the recent error logs). If/when that happens again, I'll add those logs here.

[michaeljohnalbers]

Here's an error log from a non-memory crash. There was no JVMCI error log produced.
hs_err_1_9d970e7e2623435fbf7c7fd75e4afb70.log