Async-profiler: Wall-clock profiler - hangs JVM

Created on 13 Jul 2020  ยท  32Comments  ยท  Source: jvm-profiling-tools/async-profiler

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

All 32 comments

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

stacks.lock.log

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:
image

----------------- 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;

https://github.com/jvm-profiling-tools/async-profiler/blob/5ef449c2edeb3194655dd488729ab25d58662d8a/src/os_linux.cpp#L176-L178

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:
image

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.

  1. It is a regression. Worked fine on JDK 8.
  2. It can be easily fixed in the JVM, while there is no safe straightforward workaround in library code.
  3. All profilers relying on 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

Was this page helpful?
0 / 5 - 0 ratings

Related issues

krzysztofslusarski picture krzysztofslusarski  ยท  6Comments

egwepas picture egwepas  ยท  7Comments

ryenus picture ryenus  ยท  5Comments

qqibrow picture qqibrow  ยท  5Comments

oehme picture oehme  ยท  3Comments