[GR-57950] JVMCI-native CompilerThread0 blocks main thread during the application startup

[skyitachi]

Recently, we discovered that there is a probability of the container hanging during startup. Through jstack, we found that the main thread and the JVMCI-native CompilerThread0 thread are experiencing lock contention.

JDK:

java version "21.0.5" 2024-10-15 LTS
Java(TM) SE Runtime Environment Oracle GraalVM 21.0.5+9.1 (build 21.0.5+9-LTS-jvmci-23.1-b48)
Java HotSpot(TM) 64-Bit Server VM Oracle GraalVM 21.0.5+9.1 (build 21.0.5+9-LTS-jvmci-23.1-b48, mixed mode, sharing)

OS: custom linux
Architecture: AMD64

jstack output about the two threads:
"main" #1 [94] prio=5 os_prio=0 cpu=112.55ms elapsed=3590.92s tid=0x00007ffb620d1000 nid=94 waiting for monitor entry [0x00007ffb6641c000]
java.lang.Thread.State: BLOCKED (on object monitor)
at java.util.TimeZone.setDefaultZone(java.base@21.0.5/TimeZone.java:695)
- waiting to lock <0x00000007ff8bd9b0> (a java.lang.Class for java.util.TimeZone)
at java.util.TimeZone.getDefaultRef(java.base@21.0.5/TimeZone.java:685)
at java.util.TimeZone.getDefault(java.base@21.0.5/TimeZone.java:674)
at java.util.Calendar.defaultTimeZone(java.base@21.0.5/Calendar.java:1683)
at java.util.Calendar.getInstance(java.base@21.0.5/Calendar.java:1663)
at java.text.SimpleDateFormat.initializeCalendar(java.base@21.0.5/SimpleDateFormat.java:680)
at java.text.SimpleDateFormat.(java.base@21.0.5/SimpleDateFormat.java:624)
at java.text.SimpleDateFormat.(java.base@21.0.5/SimpleDateFormat.java:603)
at com.alibaba.ttl.threadpool.agent.internal.logging.Logger$StdErrorLogger.log(Logger.java:68)
at com.alibaba.ttl.threadpool.agent.TtlTransformer.transform(TtlTransformer.java:85)
at java.lang.instrument.ClassFileTransformer.transform(java.instrument@21.0.5/ClassFileTransformer.java:244)
at sun.instrument.TransformerManager.transform(java.instrument@21.0.5/TransformerManager.java:188)
at sun.instrument.InstrumentationImpl.transform(java.instrument@21.0.5/InstrumentationImpl.java:610)
at jdk.internal.loader.URLClassPath.getLoader(java.base@21.0.5/URLClassPath.java:439)
- locked <0x00000007ff037d98> (a jdk.internal.loader.URLClassPath)
at jdk.internal.loader.URLClassPath.getResource(java.base@21.0.5/URLClassPath.java:315)
at jdk.internal.loader.BuiltinClassLoader.findClassOnClassPathOrNull(java.base@21.0.5/BuiltinClassLoader.java:757)
at jdk.internal.loader.BuiltinClassLoader.loadClassOrNull(java.base@21.0.5/BuiltinClassLoader.java:681)
- locked <0x00000007ff1460c0> (a java.lang.Object)
at jdk.internal.loader.BuiltinClassLoader.loadClass(java.base@21.0.5/BuiltinClassLoader.java:639)
at jdk.internal.loader.ClassLoaders$AppClassLoader.loadClass(java.base@21.0.5/ClassLoaders.java:188)
at java.lang.ClassLoader.loadClass(java.base@21.0.5/ClassLoader.java:526)
at sun.instrument.InstrumentationImpl.loadClassAndStartAgent(java.instrument@21.0.5/InstrumentationImpl.java:504)
at sun.instrument.InstrumentationImpl.loadClassAndCallPremain(java.instrument@21.0.5/InstrumentationImpl.java:572)

Locked ownable synchronizers:
- None

"JVMCI-native CompilerThread0" #14 [107] daemon prio=9 os_prio=0 cpu=22.82ms elapsed=3590.88s tid=0x00007ffb1dcc8000 nid=107 waiting on condition [0x00007ffafbbf9000]
java.lang.Thread.State: RUNNABLE
Compiling: 223 4 java.lang.String::hashCode (60 bytes)
at java.security.CodeSource.(java.base@21.0.5/CodeSource.java:123)
at jdk.internal.loader.BuiltinClassLoader.defineClass(java.base@21.0.5/BuiltinClassLoader.java:818)
at jdk.internal.loader.BuiltinClassLoader.findClassInModuleOrNull(java.base@21.0.5/BuiltinClassLoader.java:741)
at jdk.internal.loader.BuiltinClassLoader.findClass(java.base@21.0.5/BuiltinClassLoader.java:621)
at java.lang.ClassLoader.loadClass(java.base@21.0.5/ClassLoader.java:638)
- locked <0x00000007fe07bed0> (a java.lang.Object)
at java.lang.Class.forName(java.base@21.0.5/Class.java:625)
at java.lang.Class.forName(java.base@21.0.5/Class.java:600)
at java.util.ServiceLoader.loadProvider(java.base@21.0.5/ServiceLoader.java:859)
at java.util.ServiceLoader$ModuleServicesLookupIterator.hasNext(java.base@21.0.5/ServiceLoader.java:1084)
at java.util.ServiceLoader$2.hasNext(java.base@21.0.5/ServiceLoader.java:1309)
at java.util.ServiceLoader$3.hasNext(java.base@21.0.5/ServiceLoader.java:1393)
at sun.util.cldr.CLDRLocaleProviderAdapter.lambda$new$0(java.base@21.0.5/CLDRLocaleProviderAdapter.java:84)
at sun.util.cldr.CLDRLocaleProviderAdapter$$Lambda/0x800000063.run(java.base@21.0.5/Unknown Source)
at java.security.AccessController.executePrivileged(java.base@21.0.5/AccessController.java:809)
at java.security.AccessController.doPrivileged(java.base@21.0.5/AccessController.java:571)
at sun.util.cldr.CLDRLocaleProviderAdapter.(java.base@21.0.5/CLDRLocaleProviderAdapter.java:83)
at java.lang.invoke.DirectMethodHandle$Holder.newInvokeSpecial(java.base@21.0.5/DirectMethodHandle$Holder)
at java.lang.invoke.Invokers$Holder.invokeExact_MT(java.base@21.0.5/Invokers$Holder)
at jdk.internal.reflect.DirectConstructorHandleAccessor.invokeImpl(java.base@21.0.5/DirectConstructorHandleAccessor.java:86)
at jdk.internal.reflect.DirectConstructorHandleAccessor.newInstance(java.base@21.0.5/DirectConstructorHandleAccessor.java:62)
at java.lang.reflect.Constructor.newInstanceWithCaller(java.base@21.0.5/Constructor.java:502)
at java.lang.reflect.Constructor.newInstance(java.base@21.0.5/Constructor.java:486)
at sun.util.locale.provider.LocaleProviderAdapter.forType(java.base@21.0.5/LocaleProviderAdapter.java:194)
at sun.util.locale.provider.LocaleProviderAdapter.findAdapter(java.base@21.0.5/LocaleProviderAdapter.java:293)
at sun.util.locale.provider.LocaleProviderAdapter.getAdapter(java.base@21.0.5/LocaleProviderAdapter.java:264)
at java.util.Calendar.createCalendar(java.base@21.0.5/Calendar.java:1696)
at java.util.Calendar.getInstance(java.base@21.0.5/Calendar.java:1663)
at java.text.SimpleDateFormat.initializeCalendar(java.base@21.0.5/SimpleDateFormat.java:680)
at java.text.SimpleDateFormat.(java.base@21.0.5/SimpleDateFormat.java:624)
at java.text.SimpleDateFormat.(java.base@21.0.5/SimpleDateFormat.java:603)
at com.alibaba.ttl.threadpool.agent.internal.logging.Logger$StdErrorLogger.log(Logger.java:68)
at com.alibaba.ttl.threadpool.agent.TtlTransformer.transform(TtlTransformer.java:85)
at java.lang.instrument.ClassFileTransformer.transform(java.instrument@21.0.5/ClassFileTransformer.java:244)
at sun.instrument.TransformerManager.transform(java.instrument@21.0.5/TransformerManager.java:188)
at sun.instrument.InstrumentationImpl.transform(java.instrument@21.0.5/InstrumentationImpl.java:610)
at java.io.FileInputStream.close(java.base@21.0.5/FileInputStream.java:524)
at java.io.BufferedInputStream.close(java.base@21.0.5/BufferedInputStream.java:618)
at java.io.FilterInputStream.close(java.base@21.0.5/FilterInputStream.java:170)
at sun.util.calendar.ZoneInfoFile$1.run(java.base@21.0.5/ZoneInfoFile.java:268)
at sun.util.calendar.ZoneInfoFile$1.run(java.base@21.0.5/ZoneInfoFile.java:260)
at java.security.AccessController.executePrivileged(java.base@21.0.5/AccessController.java:778)
at java.security.AccessController.doPrivileged(java.base@21.0.5/AccessController.java:319)
at sun.util.calendar.ZoneInfoFile.loadTZDB(java.base@21.0.5/ZoneInfoFile.java:260)
at sun.util.calendar.ZoneInfoFile.(java.base@21.0.5/ZoneInfoFile.java:255)
at sun.util.calendar.ZoneInfo.getTimeZone(java.base@21.0.5/ZoneInfo.java:574)
at java.util.TimeZone.getTimeZone(java.base@21.0.5/TimeZone.java:609)
at java.util.TimeZone.setDefaultZone(java.base@21.0.5/TimeZone.java:709)
- locked <0x00000007ff8bd9b0> (a java.lang.Class for java.util.TimeZone)
at java.util.TimeZone.getDefaultRef(java.base@21.0.5/TimeZone.java:685)
at java.util.Date.normalize(java.base@21.0.5/Date.java:1197)
at java.util.Date.toString(java.base@21.0.5/Date.java:1030)
at java.lang.String.valueOf(java.base@21.0.5/String.java:4465)
at java.lang.StringBuilder.append(java.base@21.0.5/StringBuilder.java:173)
at java.util.Properties.writeDateComment(java.base@21.0.5/Properties.java:958)
at java.util.Properties.store0(java.base@21.0.5/Properties.java:919)
at java.util.Properties.store(java.base@21.0.5/Properties.java:908)
at jdk.internal.vm.VMSupport.serializePropertiesToByteArray(java.base@21.0.5/VMSupport.java:77)
at jdk.internal.vm.VMSupport.serializeSavedPropertiesToByteArray(java.base@21.0.5/VMSupport.java:115)

Locked ownable synchronizers:
- None

as the jstack output, main thread wait on lock 0x00000007ff8bd9b0, which alread acquired by JVMCI-native CompilerThread0, it's very weird the jvmci-native compilterthread0 compiling the java.lang.String::hashCode but never stop.

We are currently using Graal JIT in a production environment, and the probability of this issue occurring is not small. If it cannot be resolved, it will affect our use of Graal JIT. If there are any solutions, we hope to be informed promptly. Thanks.

ps: full jstack out
jstack.log

[selhagani]

Hi @skyitachi, thank you for reaching out to us about this.

Could you please try running your application with following flag: -XX:-UseJVMCICompiler ? let me know if using it solves your issue.

[skyitachi]

Firstly, thanks for your reply @selhagani , we already have other app servers running with normal jdk21 version(no graal jit), and they are running smoothly. The problem itself cannot be reproduced steadily, we are still collecting the cases.

I wonder why JVMCI-native CompilerThread0 need to wait on condition while compiling.

"JVMCI-native CompilerThread0" #14 [107] daemon prio=9 os_prio=0 cpu=22.82ms elapsed=3590.88s tid=0x00007ffb1dcc8000 nid=107 waiting on condition [0x00007ffafbbf9000]
java.lang.Thread.State: RUNNABLE
Compiling: 223 4 java.lang.String::hashCode (60 bytes)
at java.security.CodeSource.(java.base@21.0.5/CodeSource.java:123)
the thread was blocked due to compiling hashCode method or at java.security.CodeSource.<init>(java.base@21.0.5/CodeSource.java:123)

[skyitachi]

another case today, main thread and JVMCI-native CompilerThread0 waiting on different conditions and all stucked.

full jstack thread dump.txt