Java version:
# java -version
openjdk version "11.0.6" 2020-01-14 LTS
OpenJDK Runtime Environment Corretto-11.0.6.10.1 (build 11.0.6+10-LTS)
OpenJDK 64-Bit Server VM Corretto-11.0.6.10.1 (build 11.0.6+10-LTS, mixed mode)
Tomcat server 9.0.33.0.
after running wall clock profiler JVM hanged in such state that process was not killed and there was no coredump. This was production evironment, so we needed to resrtart application ASAP. What data can I gather when next time such hang occurs?
Server didn't accept any connection from user perspective, neither http nor jmx.
Profiler was started as agent and was managed by:
profiler.sh start -e wall -o jfr -f <file> <pid>
profiler.sh stop <pid> > /dev/null
I reproduced this bug on our test environment. What can I add is that, there is one thread that is stuck on:
"http-nio-8080-exec-18" #120 daemon prio=5 os_prio=0 cpu=73045.24ms elapsed=21287.88s tid=0x00007fc8d8603000 nid=0x5ba8 runnable [0x00007fc8a07d2000]
java.lang.Thread.State: RUNNABLE
at java.net.Inet4AddressImpl.lookupAllHostAddr([email protected]/Native Method)
at java.net.InetAddress$PlatformNameService.lookupAllHostAddr([email protected]/InetAddress.java:929)
at java.net.InetAddress.getAddressesFromNameService([email protected]/InetAddress.java:1515)
at java.net.InetAddress$NameServiceAddresses.get([email protected]/InetAddress.java:848)
- locked <0x00000000a0fb1b60> (a java.net.InetAddress$NameServiceAddresses)
at java.net.InetAddress.getAllByName0([email protected]/InetAddress.java:1505)
at java.net.InetAddress.getAllByName([email protected]/InetAddress.java:1364)
at java.net.InetAddress.getAllByName([email protected]/InetAddress.java:1298)
at java.net.InetAddress.getByName([email protected]/InetAddress.java:1248)
at java.net.InetSocketAddress.<init>([email protected]/InetSocketAddress.java:220)
And all other threads are blocked:
"http-nio-8080-exec-20" #4763 daemon prio=5 os_prio=0 cpu=32842.10ms elapsed=14435.54s tid=0x00007fc8d86ec000 nid=0x5773 waiting for monitor entry [0x00007fc89861e000]
java.lang.Thread.State: BLOCKED (on object monitor)
at java.net.InetAddress$NameServiceAddresses.get([email protected]/InetAddress.java:832)
- waiting to lock <0x00000000a0fb1b60> (a java.net.InetAddress$NameServiceAddresses)
at java.net.InetAddress.getAllByName0([email protected]/InetAddress.java:1505)
at java.net.InetAddress.getAllByName([email protected]/InetAddress.java:1364)
at java.net.InetAddress.getAllByName([email protected]/InetAddress.java:1298)
at java.net.InetAddress.getByName([email protected]/InetAddress.java:1248)
at java.net.InetSocketAddress.<init>([email protected]/InetSocketAddress.java:220)
at sun.net.NetworkClient.doConnect([email protected]/NetworkClient.java:177)
Can wall-clock do something, that could hang lookupAllHostAddr?
I'm not aware of such issue. Will take a look.
How did you notice relation to async-profiler? Does the JVM hang when you start profiling, when you stop profiling, or in the middle of the process? Is CPU idle when JVM hangs? If not, does it spend time in user or kernel space?
Application works on clustered env. 6 nodes, application was stable for few weeks. I started to run async profiler on 1 node, and after 8h of continous profiling (dumping output every minute) it hanged.
Did the same on test env. Same story, only node with async profiler died. Luckly this time I could do thread dump.
I believe that CPU has been idle. I will try to reproduce it one more time to contirm. I will also try to check if it happens on start or end.
Again I recreated it on test env.
JVM hanged 2020-07-18_01:01:08
2020-07-18_01:00:12 starting profiler for PID: 30582
2020-07-18_01:01:13 stoping profiler for PID: 30582
so it hanged during profiling.
Again, 1 thread hanged on:
"hz._hzInstance_1_hazelcast-cluster****WEB.MC.Task.Poller" #70 prio=5 os_prio=0 cpu=27132.86ms elapsed=54992.04s allocated=287M defined_classes=15 tid=0x00007fcea0dbd000 nid=0x77f1 runnable [0x00007fce9addc000]
java.lang.Thread.State: RUNNABLE
at java.net.Inet4AddressImpl.lookupAllHostAddr([email protected]/Native Method)
at java.net.InetAddress$PlatformNameService.lookupAllHostAddr([email protected]/InetAddress.java:929)
at java.net.InetAddress.getAddressesFromNameService([email protected]/InetAddress.java:1515)
at java.net.InetAddress$NameServiceAddresses.get([email protected]/InetAddress.java:848)
- locked <0x00000000dcb25b38> (a java.net.InetAddress$NameServiceAddresses)
at java.net.InetAddress.getAllByName0([email protected]/InetAddress.java:1505)
at java.net.InetAddress.getAllByName([email protected]/InetAddress.java:1364)
at java.net.InetAddress.getAllByName([email protected]/InetAddress.java:1298)
at java.net.InetAddress.getByName([email protected]/InetAddress.java:1248)
at java.net.InetSocketAddress.<init>([email protected]/InetSocketAddress.java:220)
CPU was Idle, but I connected to the server on 08:00, so I don't know if it was idle in time of hang.
Since there was wall clock profiler run I managed to dump stacks from JFR output:
Till hang the stack was:
2020-07-18T01:01:08.803+02:00[Europe/Warsaw]: com/hazelcast/internal/management/ManagementCenterService$TaskPollThread.run;com/hazelcast/internal/management/ManagementCenterService$TaskPollThread.sleep;java/lang/Thread.sleep;JVM_Sleep;pthread_cond_timedwait@@GLIBC_2.3.2 STATE_SLEEPING
next stack:
2020-07-18T01:01:08.853+02:00[Europe/Warsaw]: com/hazelcast/internal/management/ManagementCenterService$TaskPollThread.run;com/hazelcast/internal/management/ManagementCenterService$TaskPollThread.processTask;com/hazelcast/internal/management/ManagementCenterService$TaskPollThread.openTaskInputStream;sun/net/www/protocol/http/HttpURLConnection.getInputStream;sun/net/www/protocol/http/HttpURLConnection.getInputStream0;sun/net/www/protocol/http/HttpURLConnection.connect;sun/net/www/protocol/http/HttpURLConnection.plainConnect;sun/net/www/protocol/http/HttpURLConnection.plainConnect0;sun/net/www/protocol/http/HttpURLConnection.getNewHttpClient;sun/net/www/http/HttpClient.New;sun/net/www/http/HttpClient.New;sun/net/www/http/HttpClient.<init>;sun/net/www/http/HttpClient.openServer;sun/net/www/http/HttpClient.openServer;sun/net/NetworkClient.doConnect;java/net/InetSocketAddress.<init>;java/net/InetAddress.getByName;java/net/InetAddress.getAllByName;java/net/InetAddress.getAllByName;java/net/InetAddress.getAllByName0;java/net/InetAddress$NameServiceAddresses.get;java/net/InetAddress.getAddressesFromNameService;java/net/InetAddress$PlatformNameService.lookupAllHostAddr;java/net/Inet4AddressImpl.lookupAllHostAddr;__libc_poll STATE_SLEEPING
State is sleeping. Hope that helped.
Thank you for the update. The problem is clearer now.
It seems to be related to my workaround for JDK-8237858.
Will see how I can fix it.
Great :-) I will be more then happy to test your fix, when it's ready.
To workaround JDK bug in Socket.accept() implementation, async-profiler restarted interrupted poll() syscalls. However, this mistakently affected other poll() calls, including the one in address lookup.
I committed the fix.
Thx, I'm retesting it on test env. I will try to test it on prod next week.
Unfortunately JVM hanged again, after 2 days of profiling. My admins were faster then me, and they restarted my application. Looks like a different problem, there was no BLOCKED threads on stacktrace soon before freeze. I will try to reproduce one more time and fetch stacks from manually generated core dump.
Did you restart the JVM before testing the updated profiler? Otherwise the already loaded version would take effect.
(Just to make sure, because this is a common issue when a newer library does not work after an older one has been loaded into the process).
Yes, JVM was restarted.
Here are stacks from core dump. If yuo need something else from core dump, let me know. Generated with:
/opt/java/bin/jhsdb jstack --mixed --locks --exe /opt/java/bin/java --core core.22557
Symptoms: JVM is hanged. Nothing works. It doesn't process http request, I cannot attach to it with JCMD and JStack.
1 thread is consuming 100% CPU:

----------------- 22650 -----------------
"Attach Listener" #30 daemon prio=9 tid=0x00007f4854009800 nid=0x587a runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
JavaThread state: _thread_in_native
0x00007f4840dcc60e _ZN8Profiler4stopEv + 0x7e
Locked ownable synchronizers:
- None
Running perf on that process shows:
Attach Listener 22650 21048436.791058: 250000 cpu-clock:
7f4840dcc60e Profiler::stop+0x7e (/opt/_____/profiler/wall/build/libasyncProfiler.so)
20746f6e20736920 [unknown] ([unknown])
Assembly:
โ0x7f4840dcc5c0 <_ZN8Profiler4stopEv+48> mov 0x80c8(%rbx),%rdi โ
โ0x7f4840dcc5c7 <_ZN8Profiler4stopEv+55> mov (%rdi),%rax โ
โ0x7f4840dcc5ca <_ZN8Profiler4stopEv+58> callq *0x20(%rax) โ
โ0x7f4840dcc5cd <_ZN8Profiler4stopEv+61> xor %esi,%esi โ
โ0x7f4840dcc5cf <_ZN8Profiler4stopEv+63> mov %rbx,%rdi โ
โ0x7f4840dcc5d2 <_ZN8Profiler4stopEv+66> callq 0x7f4840dc5b10 <_ZN8Profiler23switchNativeMethodTrapsEb@plt> โ
โ0x7f4840dcc5d7 <_ZN8Profiler4stopEv+71> xor %esi,%esi โ
โ0x7f4840dcc5d9 <_ZN8Profiler4stopEv+73> mov %rbx,%rdi โ
โ0x7f4840dcc5dc <_ZN8Profiler4stopEv+76> callq 0x7f4840dc6570 <_ZN8Profiler18switchThreadEventsE14jvmtiEventMode@plt> โ
โ0x7f4840dcc5e1 <_ZN8Profiler4stopEv+81> mov %rbx,%rdi โ
โ0x7f4840dcc5e4 <_ZN8Profiler4stopEv+84> callq 0x7f4840dc58c0 <_ZN8Profiler21updateJavaThreadNamesEv@plt> โ
โ0x7f4840dcc5e9 <_ZN8Profiler4stopEv+89> mov %rbx,%rdi โ
โ0x7f4840dcc5ec <_ZN8Profiler4stopEv+92> callq 0x7f4840dc5a50 <_ZN8Profiler23updateNativeThreadNamesEv@plt> โ
โ0x7f4840dcc5f1 <_ZN8Profiler4stopEv+97> lea 0x408148(%rbx),%rdx โ
โ0x7f4840dcc5f8 <_ZN8Profiler4stopEv+104> mov $0x10,%ecx โ
โ0x7f4840dcc5fd <_ZN8Profiler4stopEv+109> xor %edi,%edi โ
โ0x7f4840dcc5ff <_ZN8Profiler4stopEv+111> mov $0x1,%esi โ
โ0x7f4840dcc604 <_ZN8Profiler4stopEv+116> nopl 0x0(%rax) โ
โ0x7f4840dcc608 <_ZN8Profiler4stopEv+120> mov %edi,%eax โ
โ0x7f4840dcc60a <_ZN8Profiler4stopEv+122> lock cmpxchg %esi,(%rdx) โ
>โ0x7f4840dcc60e <_ZN8Profiler4stopEv+126> jne 0x7f4840dcc659 <_ZN8Profiler4stopEv+201> โ
โ0x7f4840dcc610 <_ZN8Profiler4stopEv+128> add $0x4,%rdx โ
โ0x7f4840dcc614 <_ZN8Profiler4stopEv+132> sub $0x1,%ecx โ
โ0x7f4840dcc617 <_ZN8Profiler4stopEv+135> jne 0x7f4840dcc608 <_ZN8Profiler4stopEv+120> โ
โ0x7f4840dcc619 <_ZN8Profiler4stopEv+137> lea 0x80c0(%rbx),%rdi โ
โ0x7f4840dcc620 <_ZN8Profiler4stopEv+144> callq 0x7f4840dc55e0 <_ZN14FlightRecorder4stopEv@plt> โ
โ0x7f4840dcc625 <_ZN8Profiler4stopEv+149> xor %eax,%eax โ
โ0x7f4840dcc627 <_ZN8Profiler4stopEv+151> nopw 0x0(%rax,%rax,1) โ
โ0x7f4840dcc630 <_ZN8Profiler4stopEv+160> lock subl $0x1,0x408148(%rbx,%rax,1) โ
โ0x7f4840dcc639 <_ZN8Profiler4stopEv+169> add $0x4,%rax โ
โ0x7f4840dcc63d <_ZN8Profiler4stopEv+173> cmp $0x40,%rax โ
โ0x7f4840dcc641 <_ZN8Profiler4stopEv+177> jne 0x7f4840dcc630 <_ZN8Profiler4stopEv+160> โ
โ0x7f4840dcc643 <_ZN8Profiler4stopEv+179> mov 0x221796(%rip),%rax # 0x7f4840fedde0 โ
โ0x7f4840dcc64a <_ZN8Profiler4stopEv+186> movl $0x0,0x28(%rbx) โ
โ0x7f4840dcc651 <_ZN8Profiler4stopEv+193> mov (%rax),%rbp โ
โ0x7f4840dcc654 <_ZN8Profiler4stopEv+196> jmpq 0x7f4840dcc5ab <_ZN8Profiler4stopEv+27> โ
โ0x7f4840dcc659 <_ZN8Profiler4stopEv+201> pause โ
โ0x7f4840dcc65b <_ZN8Profiler4stopEv+203> jmp 0x7f4840dcc608 <_ZN8Profiler4stopEv+120> โ
โ0x7f4840dcc65d <_ZN8Profiler4stopEv+205> mov %rax,%rbp โ
โ0x7f4840dcc660 <_ZN8Profiler4stopEv+208> mov %rbx,%rdi โ
โ0x7f4840dcc663 <_ZN8Profiler4stopEv+211> callq 0x7f4840dc6aa0 <_ZN5Mutex6unlockEv@plt> โ
โ0x7f4840dcc668 <_ZN8Profiler4stopEv+216> mov %rbp,%rdi โ
โ0x7f4840dcc66b <_ZN8Profiler4stopEv+219> callq 0x7f4840dc6990 <_Unwind_Resume@plt> โ
I'm not really good in ASM and C++, but I believe this is part of async-profiler code, that hanged:
for (int i = 0; i < CONCURRENCY_LEVEL; i++) _locks[i].lock();
2 things looks strange too:
sun.jvm.hotspot.debugger.UnmappedAddressException: 4abff8d9f53560
at jdk.hotspot.agent/sun.jvm.hotspot.debugger.PageCache.checkPage(PageCache.java:208)
at jdk.hotspot.agent/sun.jvm.hotspot.debugger.PageCache.getData(PageCache.java:63)
at jdk.hotspot.agent/sun.jvm.hotspot.debugger.DebuggerBase.readBytes(DebuggerBase.java:225)
at jdk.hotspot.agent/sun.jvm.hotspot.debugger.linux.LinuxDebuggerLocal.readCInteger(LinuxDebuggerLocal.java:494)
at jdk.hotspot.agent/sun.jvm.hotspot.debugger.DebuggerBase.readAddressValue(DebuggerBase.java:462)
at jdk.hotspot.agent/sun.jvm.hotspot.debugger.linux.LinuxDebuggerLocal.readAddress(LinuxDebuggerLocal.java:429)
at jdk.hotspot.agent/sun.jvm.hotspot.debugger.linux.LinuxAddress.getAddressAt(LinuxAddress.java:74)
at jdk.hotspot.agent/sun.jvm.hotspot.debugger.linux.amd64.LinuxAMD64CFrame.sender(LinuxAMD64CFrame.java:68)
Do not have such exception on this application before crash.
"http-nio-8080-exec-1" #85 daemon prio=5 tid=0x00007f48a91cc000 nid=0x58f0 waiting for monitor entry [0x00007f482e1fa000]
java.lang.Thread.State: BLOCKED (on object monitor)
JavaThread state: _thread_blocked
0x00007f48b0e98da2 __pthread_cond_timedwait + 0x132
0x00007f48afdebb79 _ZN13ObjectMonitor6EnterIEP6Thread + 0x1e9
0x00007f48afdec278 _ZN13ObjectMonitor5enterEP6Thread.part.93 + 0x1f8
0x00007f48aff86af2 _ZN18ObjectSynchronizer10fast_enterE6HandleP9BasicLockbP6Thread + 0x2d2
0x00007f48afef1144 _ZN13SharedRuntime26complete_monitor_locking_CEP7oopDescP9BasicLockP10JavaThread + 0x194
Locked ownable synchronizers:
- <0x0000000089d87648>, (a java/util/concurrent/ThreadPoolExecutor$Worker)
One more thing - I'm running async-profiler on production with the same aplliaction, but on CPU mode. It is stable, it is running almost 2 weeks, no hangs, so this issue looks like "wall-clock" specifiic.
I found also such a stack trace in coredump file:
(gdb) thread 98
[Switching to thread 98 (Thread 0x7f48296db700 (LWP 19501))]
#0 0x00007f48b07ac57c in __lll_lock_wait_private () from /lib64/libc.so.6
(gdb) where
#0 0x00007f48b07ac57c in __lll_lock_wait_private () from /lib64/libc.so.6
#1 0x00007f48b0728af5 in _L_lock_17166 () from /lib64/libc.so.6
#2 0x00007f48b0725b33 in malloc () from /lib64/libc.so.6
#3 0x00007f48b10bafd8 in tls_get_addr_tail () from /lib64/ld-linux-x86-64.so.2
#4 0x00007f48b10c09a8 in __tls_get_addr () from /lib64/ld-linux-x86-64.so.2
#5 0x00007f48afb04936 in jni_GetEnv () from /opt/jdk_11.0.6.10.1_corretto/lib/server/libjvm.so
#6 0x00007f4840dc8517 in Profiler::getJavaTraceAsync(void*, ASGCT_CallFrame*, int) () from /opt/mplus/profiler/wall/build/libasyncProfiler.so
#7 0x00007f4840dc8c26 in Profiler::recordSample(void*, unsigned long long, int, _jmethodID*, ThreadState) () from /opt/mplus/profiler/wall/build/libasyncProfiler.so
#8 <signal handler called>
#9 0x00007f48b07223d0 in _int_malloc () from /lib64/libc.so.6
#10 0x00007f48b0725adc in malloc () from /lib64/libc.so.6
#11 0x00007f48b10bafd8 in tls_get_addr_tail () from /lib64/ld-linux-x86-64.so.2
#12 0x00007f48b10c09a8 in __tls_get_addr () from /lib64/ld-linux-x86-64.so.2
#13 0x00007f48affc240c in Thread::initialize_thread_current() () from /opt/jdk_11.0.6.10.1_corretto/lib/server/libjvm.so
#14 0x00007f48afe16ed7 in thread_native_entry(Thread*) () from /opt/jdk_11.0.6.10.1_corretto/lib/server/libjvm.so
#15 0x00007f48b0e94e65 in start_thread () from /lib64/libpthread.so.0
#16 0x00007f48b079e88d in clone () from /lib64/libc.so.6
As I understand, thread 98 is stuck, but contains one of the spinlocks, so "stop" command cannot succed.
I believe this may be an issue:
https://stackoverflow.com/questions/40049751/malloc-inside-linux-signal-handler-cause-deadlock
The implementation of malloc might be grabbing internal glibc lock. We know that signal handlers are called asynchronously. If the thread during normal execution had malloc'd and was interrupted to handle signal we have a problem if signal handler function uses malloc. Signal handler malloc would try to get the lock but it isn't available because the same thread had got it during its normal execution. And you have deadlock. It is for this reason signal handlers should be lean and non-AS-safe function should not be called.
Thank you for the thorough analysis. The problem is clear now.
Actually, I've fixed a similar bug on macOS a while ago, but I was under impression that it wasn't relevant on Linux. However, it seems like pthread_getspecific calls malloc on Linux, too.
As a temporary workaround, try to replace the following function to return false;
Meanwhile I'll look for a better solution.
Ok, I repleaced it and run such compilation on my test environment.
Looks stable so far, I'm testing it at production at night, no hangs so far.
Unfortunately this workaround causes, that many of my stack traces is lost, it doesn't log java stacks that ends:
org/apache/http/impl/client/CloseableHttpClient.execute
org/apache/http/impl/client/CloseableHttpClient.execute
org/apache/http/impl/client/InternalHttpClient.doExecute
org/apache/http/impl/execchain/RedirectExec.execute
org/apache/http/impl/execchain/RetryExec.execute
org/apache/http/impl/execchain/ProtocolExec.execute
org/apache/http/impl/execchain/MainClientExec.execute
org/apache/http/protocol/HttpRequestExecutor.execute
org/apache/http/protocol/HttpRequestExecutor.doReceiveResponse
org/apache/http/impl/conn/CPoolProxy.receiveResponseHeader
org/apache/http/impl/DefaultBHttpClientConnection.receiveResponseHeader
org/apache/http/impl/io/AbstractMessageParser.parse
org/apache/http/impl/conn/DefaultHttpResponseParser.parseHead
org/apache/http/impl/conn/DefaultHttpResponseParser.parseHead
org/apache/http/impl/io/SessionInputBufferImpl.readLine
org/apache/http/impl/io/SessionInputBufferImpl.fillBuffer
org/apache/http/impl/io/SessionInputBufferImpl.streamRead
java/net/SocketInputStream.read
java/net/SocketInputStream.read
java/net/SocketInputStream.socketRead
java/net/SocketInputStream.socketRead0
__libc_recv
and that is huge part of my application.
I will test it for a week on production, but I will have to wait for other solution.
Bottom of the flame graph:

I don't know if this is not an issue with Glibc:
https://sourceware.org/bugzilla/show_bug.cgi?id=21609
https://bugzilla.redhat.com/show_bug.cgi?id=1440287
I'm testing it on 2.17 version. @apangin Can this be related to those bugs?
I can test compilation with flag -ftls-model=initial-exec as suggested in those bugs.
No, it's another issue.
After investigation I came to conclusion that this is a JVM bug appeared with JDK-8132510. Since JDK 9 the implementation of Thread::current() in HotSpot was changed from pthread_getspecific to a glibc thread-local variable. However, the latter is not async signal safe. Formally, pthread_getspecific is not safe either, but in practice it is.
AsyncGetCallTrace API requires a pointer to JNIEnv*. But all legal ways to get JNIEnv* inside a signal handler result in Thread::current() call, which in turn accesses thread-local variable and causes a non-reentrant call to malloc.
Why I think this is a VM bug.
AsyncGetCallTrace are potentially affected. There should be a safe way provided by the JVM to call AsyncGetCallTrace.There was a long discussion thread about signal safety of the proposed solution, but unfortunately it did not consider profiling scenarios.
So, I think I should probably resurrect the discussion again. Meanwhile I came up with an idea for a workaround. Will post the update a bit later.
Can you tell which modes are affected by this?
From my experience CPU mode never crashed JVM.
The bug affects only wall and itimer modes.
It also affects cpu on macOS, where cpu profiling is implemented as a variant of wall-clock mode.
I pushed the workaround. Now async-profiler attempts to peek TLS by pthread_getspecific before calling GetEnv.
Great, thank you for quick fix. I already deployed new version to test environment.
So far so good, 24h on 2 nodes on test env., everything is working. I will try to test it on production next week.
@apangin I believe it is fixed. 5 days on production, and 7 days on 2 test nodes, no hangs. Do you want to do something more in this issue, or should I just close it?
Thank you for testing. I think we're done with this issue.
Great, I believe that this issue deserved at least minor version release :)
Released 1.8