Async-profiler: JVM Crash with 1.8.2 + OpenJDK 8u275

[SylvainJuge]

This issue has been initially reported in Elastic forum.

Context:

• elastic-apm-agent version 1.19.0 that ships with async-profiler 1.8.2 (md5 of .so is 7b0005bb0afc7e225ffe8372878fd01a)
• JVM : OpenJDK 8 upate 275

We don't have the regular hs_err_pid* crash report, but the following error has been reported:

*** Error in `/opt/java/1.8.0_275/bin/java': double free or corruption (!prev): 0x00007f0dc47550b0 ***
======= Backtrace: =========
/lib64/libc.so.6(+0x81299)[0x7f0ecfbce299]
/opt/java/1.8.0_275/jre/lib/amd64/server/libjvm.so(+0x64edab)[0x7f0ecf151dab]
/opt/java/1.8.0_275/jre/lib/amd64/server/libjvm.so(+0x7aa513)[0x7f0ecf2ad513]
/opt/java/1.8.0_275/jre/lib/amd64/server/libjvm.so(+0x79ebc4)[0x7f0ecf2a1bc4]
/home/temp/tomcat_temp/libasyncProfiler-linux-x64-7b0005bb0afc7e225ffe8372878fd01a.so(_ZN8Profiler17getJavaTraceJvmtiEP15_jvmtiFrameInfoP15ASGCT_CallFramei+0x64)[0x7f0dde2b58f4]
/home/temp/tomcat_temp/libasyncProfiler-linux-x64-7b0005bb0afc7e225ffe8372878fd01a.so(_ZN8Profiler17getJavaTraceAsyncEPvP15ASGCT_CallFramei+0x15b)[0x7f0dde2b5c9b]
/home/temp/tomcat_temp/libasyncProfiler-linux-x64-7b0005bb0afc7e225ffe8372878fd01a.so(_ZN8Profiler12recordSampleEPvyiP10_jmethodID11ThreadState+0x20c)[0x7f0dde2b632c]
/lib64/libpthread.so.0(+0xf630)[0x7f0ed0346630]
/lib64/libpthread.so.0(pthread_cond_timedwait+0x132)[0x7f0ed0342de2]
/opt/java/1.8.0_275/jre/lib/amd64/server/libjvm.so(+0x964b5a)[0x7f0ecf467b5a]
/opt/java/1.8.0_275/jre/lib/amd64/server/libjvm.so(+0xb00cb2)[0x7f0ecf603cb2]
[0x7f0eb2fa89ea]
======= Memory map: ========
649000000-722280000 rw-p 00000000 00:00 0 
722280000-743000000 ---p 00000000 00:00 0 
743000000-7ab000000 rw-p 00000000 00:00 0 
7ab000000-7c0000000 ---p 00000000 00:00 0 
7c0000000-7c2060000 rw-p 00000000 00:00 0 
7c2060000-800000000 ---p 00000000 00:00 0 
556d4cdac000-556d4cdad000 r-xp 00000000 08:03 11272234                   /opt/java/1.8.0_275/bin/java
556d4cfac000-556d4cfad000 r--p 00000000 08:03 11272234                   /opt/java/1.8.0_275/bin/java
556d4cfad000-556d4cfae000 rw-p 00001000 08:03 11272234                   /opt/java/1.8.0_275/bin/java
556d4e340000-556d4e361000 rw-p 00000000 00:00 0                          [heap]
7f0c7cf7a000-7f0c7d13a000 rw-p 00000000 00:00 0 
7f0c7d13a000-7f0c7d17a000 ---p 00000000 00:00 0 
7f0c7d17a000-7f0c7d37a000 rw-p 00000000 00:00 0 
7f0c7d37a000-7f0c7d57a000 rw-p 00000000 00:00 0 
7f0c7d57a000-7f0c7d77a000 rw-p 00000000 00:00 0 
7f0c7d77a000-7f0c7d97a000 rw-p 00000000 00:00 0 
7f0c7d97a000-7f0c7db7a000 rw-p 00000000 00:00 0 
7f0c7db7a000-7f0c7dd7a000 rw-p 00000000 00:00 0 
7f0c7dd7a000-7f0c7df7a000 rw-p 00000000 00:00 0 
7f0c7df7a000-7f0c7e17a000 rw-p 00000000 00:00 0 
7f0c7e17a000-7f0c7e37a000 rw-p 00000000 00:00 0 
7f0c7e37a000-7f0c7e3a3000 r-xp 00000000 08:03 2622258                    /usr/lib64/libpng15.so.15.13.0
7f0c7e3a3000-7f0c7e5a3000 ---p 00029000 08:03 2622258                    /usr/lib64/libpng15.so.15.13.0
7f0c7e5a3000-7f0c7e5a4000 r--p 00029000 08:03 2622258                    /usr/lib64/libpng15.so.15.13.0
7f0c7e5a4000-7f0c7e5a5000 rw-p 0002a000 08:03 2622258                    /usr/lib64/libpng15.so.15.13.0
7f0c7e5a5000-7f0c7e5b4000 r-xp 00000000 08:03 2622237                    /usr/lib64/libbz2.so.1.0.6
7f0c7e5b4000-7f0c7e7b3000 ---p 0000f000 08:03 2622237                    /usr/lib64/libbz2.so.1.0.6
7f0c7e7b3000-7f0c7e7b4000 r--p 0000e000 08:03 2622237                    /usr/lib64/libbz2.so.1.0.6
7f0c7e7b4000-7f0c7e7b5000 rw-p 0000f000 08:03 2622237                    /usr/lib64/libbz2.so.1.0.6
7f0c7e7b5000-7f0c7e7ca000 r-xp 00000000 08:03 2622137                    /usr/lib64/libz.so.1.2.7
7f0c7e7ca000-7f0c7e9c9000 ---p 00015000 08:03 2622137                    /usr/lib64/libz.so.1.2.7
7f0c7e9c9000-7f0c7e9ca000 r--p 00014000 08:03 2622137                    /usr/lib64/libz.so.1.2.7
7f0c7e9ca000-7f0c7e9cb000 rw-p 00015000 08:03 2622137                    /usr/lib64/libz.so.1.2.7
7f0c7e9cb000-7f0c7ea82000 r-xp 00000000 08:03 2622235                    /usr/lib64/libfreetype.so.6.14.0
7f0c7ea82000-7f0c7ec82000 ---p 000b7000 08:03 2622235                    /usr/lib64/libfreetype.so.6.14.0
7f0c7ec82000-7f0c7ec89000 r--p 000b7000 08:03 2622235                    /usr/lib64/libfreetype.so.6.14.0
7f0c7ec89000-7f0c7ec8a000 rw-p 000be000 08:03 2622235                    /usr/lib64/libfreetype.so.6.14.0
7f0c7ec8a000-7f0c7ecf2000 r-xp 00000000 08:03 11272346                   /opt/java/1.8.0_275/jre/lib/amd64/libfontmanager.so
7f0c7ecf2000-7f0c7eef2000 ---p 00068000 08:03 11272346                   /opt/java/1.8.0_275/jre/lib/amd64/libfontmanager.so
7f0c7eef2000-7f0c7eef5000 r--p 00068000 08:03 11272346                   /opt/java/1.8.0_275/jre/lib/amd64/libfontmanager.so
7f0c7eef5000-7f0c7eef6000 rw-p 0006b000 08:03 11272346                   /opt/java/1.8.0_275/jre/lib/amd64/libfontmanager.so
7f0c7eef6000-7f0c7f0f7000 rw-p 00000000 00:00 0 
7f0c7f0f7000-7f0c7f2f7000 rw-p 00000000 00:00 0 
.............. 

[apangin]

Decoded stack trace:

free
FreeHeap(to_dealloc_jmeths)
InstanceKlass::get_jmethod_id
JvmtiEnvBase::get_stack_trace
JvmtiEnv::GetStackTrace
Profiler::getJavaTraceJvmti
Profiler::getJavaTraceAsync
Profiler::recordSample
<signal handler>
pthread_cond_timedwait
Parker::park
Unsafe_Park

Looks like two threads concurrently tried to expand or create jmethod_id cache of the same class.
Since there was GC in progress (at safepoint), HotSpot thought locking was not necessary:

    if (Threads::number_of_threads() == 0 ||
        SafepointSynchronize::is_at_safepoint()) {
      // we're single threaded or at a safepoint - no locking needed
      id = get_jmethod_id_fetch_or_update(ik_h, idnum, new_id, new_jmeths,
                                          &to_dealloc_id, &to_dealloc_jmeths);

I am not quite sure how this could happen, as async-profiler preallocates all jmethod_ids. The only possible reason I see - is RedefineClasses call, which invalidates jmethod_id cache.

A simple workaround is to disable stack walking during GC. This can be achieved by passing safemode=16 option to the async-profiler agent. This will certainly help to avoid crash at the cost of not collecting Java stack traces during GC.

A better solution may be to involve our own locking in async-profiler around JvmtiEnv::GetStackTrace. This should be done very carefully in order to avoid deadlocks.

I'll also investigate how RedefineClasses may affect this issue. Will come back when I have more info.

[apangin]

I've built a special version with an alternative workaround: async-profiler-1.8.2-fix-linux-x64.tar.gz

Instead of skipping all Java stacks during GC, this fix allows to collect them in a single-threaded mode. Concurrent attempts to collect such stacks are still rejected. This version does not require safemode option.

I'll be glad to know if the fix works for the reporter of the original bug.

[aaamber]

Thanks for your time! I'm the reporter of the original bug and we haven't seen any issues after setting safemode=16 last weekend.

[eyalkoren]

@apangin thanks!

@aaamber please try this agent snapshot without the async_profiler_safe_mode=16 config and see if it resolves the problem.

[aaamber]

@eyalkoren I set up the agent snapshot five days ago and haven't seen any issues related to JVM since then.

[apangin]

@aaamber Thank you for the confirmation. Good to know the fix works.
But I think I have an idea of yet a better fix, that will allow to retain all profiling samples.
If you don't mind spending some more time on testing that, we'll prepare a new build as soon as I verify the fix locally.

[apangin]

Here is an updated version: async-profiler-1.8.2-fix2-linux-x64.tar.gz

The idea is to intercept RedefineClasses/RetransformClasses calls and update jmethoIDs right after transformation. This approach allows collecting all stack traces during GC.

[eyalkoren]

@apangin thanks for the enhanced fix!

@aaamber please try this agent snapshot without setting the async_profiler_safe_mode config and see if it resolves the problem.

[aaamber]

I've been using the snapshot without setting the async_profiler_safe_mode for two weeks and no issues were found. Thanks for fixing it!

[apangin]

@aaamber Thank you very much for verifying. The fix is merged into the master brach and will get in the nearest release of async-profiler.