sigsegv crash about honest-profiler

[RichardWarburton]

Do you have a testcase that reproduces this? If not, do you know if there was any kind of invokedynamic involved, or possible Java 8 Lambdas? There's an open JDK issue around invokedynamic stuff at https://bugs.openjdk.java.net/browse/JDK-8026328.

[RichardWarburton]

Also, which JDK version were you using when this crash happened? Just pasting the output of:

java -version

gives the information needed.

[ceeaspb]

sadly no test case apart from running gatling, where it has only occurred once in possibly 100 times. I expect though with some perseverance it could be reproduced but in a couple of weeks as I am away.

$ java -version
java version "1.8.0_05"
Java(TM) SE Runtime Environment (build 1.8.0_05-b13)
Java HotSpot(TM) 64-Bit Server VM (build 25.5-b02, mixed mode)

gatling has a fair number command line args:

-agentpath:/home/vagrant/git/RichardWarburton/honest-profiler/build/liblagent.so -XX:+UseThreadPriorities -XX:T
hreadPriorityPolicy=42 -Xms2G -Xmx2G -Xmn1G -XX:+HeapDumpOnOutOfMemoryError -XX:+AggressiveOpts -XX:+OptimizeStringConcat
 -XX:+UseFastAccessorMethods -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+CMSParallelRemarkEnabled -Djava.net.preferIPv4
Stack=true -Djava.net.preferIPv6Addresses=false

not sure whether invokedynamic is used.
gatling is not supported in java 8, I have just been testing out a few different things, regardless a crash shouldn't happen...

[RichardWarburton]

Thanks for the information.

I was asking about invokedynamic and Java 8 because there were a couple of OpenJDK bug reports with similar stack traces and the stacktrace shows that the segfault is actually caused by code in the hotspot codebase rather than in the profiler.

[FauxFaux]

I got a similar segfault, also no core dump. This was possibly while the JVM was exiting? It was certainly after the last log line I expected the thing to output:

One of your monitoring interfaces is having trouble resolving its stack traces.  GetMethodName on a jmethodID involved in a stacktrace resulted in an INVALID_METHODID error which usually indicates its declaring class has been unloaded.
Unexpected JVMTI error 23 in GetMethodName#
# A fatal error has been detected by the Java Runtime Environment:

....


Stack: [0x00007fb509150000,0x00007fb509251000],  sp=0x00007fb50924f938,  free space=1022k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
C  0x00007fb4fd8d3998
V  [libjvm.so+0x6cc236]  jvmti_GetMethodName+0x1f6
C  [liblagent.so+0x92b3]  Profiler::lookupFrameInformation(JVMPI_CallFrame const&, _jvmtiEnv*, MethodListener&)+0x43
C  [liblagent.so+0x88ea]  LogWriter::record(JVMPI_CallTrace const&)+0x6a
C  [liblagent.so+0x84ba]  CircularQueue::pop()+0x2a
C  [liblagent.so+0x8c69]  Processor::run()+0x19
V  [libjvm.so+0x736512]  JvmtiAgentThread::call_start_function()+0xc2
V  [libjvm.so+0x9e2fef]  JavaThread::thread_main_inner()+0xdf
V  [libjvm.so+0x9e31b5]  JavaThread::run()+0x1b5
V  [libjvm.so+0x8a0038]  java_start(Thread*)+0x108

java version "1.8.0_11"
Java(TM) SE Runtime Environment (build 1.8.0_11-b12)
Java HotSpot(TM) 64-Bit Server VM (build 25.11-b03, mixed mode)

Linux 3.13.0-30-generic #54-Ubuntu SMP Mon Jun 9 22:45:01 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux

[RichardWarburton]

I would strongly recommend against using the u11 release in general. It seems to be a bit of a duff release from a tooling point of view.

http://www.infoq.com/news/2014/08/Java8-U11-Broke-Tools

[RichardWarburton]

Sorry - I should have clarified in the previous comment that obviously this is still a serious bug which I am investigating.

[jerrinot]

Hi,

I've ran into this issue on Oracle JDK 8u20.

Stack: [0x00007f5c741ac000,0x00007f5c742ad000],  sp=0x00007f5c742abb10,  free space=1022k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V  [libjvm.so+0x8731a4]  Method::checked_resolve_jmethod_id(_jmethodID*)+0x34
V  [libjvm.so+0x70a1e6]  jvmti_GetMethodName+0x1f6
C  [liblagent.so+0x9053]  Profiler::lookupFrameInformation(JVMPI_CallFrame const&, _jvmtiEnv*, MethodListener&)+0x43
C  [liblagent.so+0x868a]  LogWriter::record(JVMPI_CallTrace const&)+0x6a
C  [liblagent.so+0x825a]  CircularQueue::pop()+0x2a
C  [liblagent.so+0x8a09]  Processor::run()+0x19
V  [libjvm.so+0x7744f2]  JvmtiAgentThread::call_start_function()+0xc2
V  [libjvm.so+0xa2990f]  JavaThread::thread_main_inner()+0xdf
V  [libjvm.so+0xa29a3c]  JavaThread::run()+0x11c
V  [libjvm.so+0x8e75f8]  java_start(Thread*)+0x108
C  [libpthread.so.0+0x8182]  start_thread+0xc2

My code does not use lambda / invokedynamic.

[jerrinot]

I managed to reproduce it on

java version "1.7.0_65"
OpenJDK Runtime Environment (IcedTea 2.5.3) (7u71-2.5.3-0ubuntu0.14.04.1)
OpenJDK 64-Bit Server VM (build 24.65-b04, mixed mode)

a compressed coredump has 161MB. Would you like me to upload it somewhere?

(gdb) bt
#0  0x00007f924efc0bb9 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#1  0x00007f924efc3fc8 in __GI_abort () at abort.c:89
#2  0x00007f924e3148f9 in os::abort (dump_core=<optimized out>) at /build/buildd/openjdk-7-7u71-2.5.3/build/openjdk/hotspot/src/os/linux/vm/os_linux.cpp:1615
#3  0x00007f924e497f7f in VMError::report_and_die (this=this@entry=0x7f923e140520)
    at /build/buildd/openjdk-7-7u71-2.5.3/build/openjdk/hotspot/src/share/vm/utilities/vmError.cpp:1053
#4  0x00007f924e31d6df in JVM_handle_linux_signal (sig=11, info=0x7f923e140770, ucVoid=0x7f923e140640, abort_if_unrecognized=<optimized out>)
    at /build/buildd/openjdk-7-7u71-2.5.3/build/openjdk/hotspot/src/os_cpu/linux_x86/vm/os_linux_x86.cpp:531
#5  <signal handler called>
#6  resolve_external_guard (handle=0x7f0000000000) at /build/buildd/openjdk-7-7u71-2.5.3/build/openjdk/hotspot/src/share/vm/runtime/jniHandles.hpp:194
#7  checked_resolve_jmethod_id (mid=0x7f0000000000) at /build/buildd/openjdk-7-7u71-2.5.3/build/openjdk/hotspot/src/share/vm/runtime/jniHandles.hpp:215
#8  jvmti_GetMethodName (env=0x7f9248004630, method=0x7f0000000000, name_ptr=0x7f923e140c78, signature_ptr=0x0, generic_ptr=<optimized out>)
    at ../generated/jvmtifiles/jvmtiEnter.cpp:4222
#9  0x00007f924cae4db3 in GetMethodName (generic_ptr=0x0, signature_ptr=0x0, name_ptr=0x7f923e140c78, method=<optimized out>, this=0x7f9248004630)
    at /usr/lib/jvm/java-8-oracle/include/jvmti.h:2283
#10 Profiler::lookupFrameInformation (frame=..., jvmti=0x7f9248004630, logWriter=...) at /home/jara/devel/oss/honest-profiler/src/main/cpp/profiler.cpp:47
#11 0x00007f924cae456a in LogWriter::record (this=0x7f9248005090, trace=...) at /home/jara/devel/oss/honest-profiler/src/main/cpp/log_writer.cpp:38
#12 0x00007f924cae413a in CircularQueue::pop (this=0x7f924c8d8010) at /home/jara/devel/oss/honest-profiler/src/main/cpp/circular_queue.cpp:54
#13 0x00007f924cae48e9 in Processor::run (this=0x7f9248005390) at /home/jara/devel/oss/honest-profiler/src/main/cpp/processor.cpp:48
#14 0x00007f924e1f958b in call_start_function (this=0x7f92480bf800) at /build/buildd/openjdk-7-7u71-2.5.3/build/openjdk/hotspot/src/share/vm/prims/jvmtiImpl.cpp:93
#15 JvmtiAgentThread::start_function_wrapper (thread=0x7f92480bf800, __the_thread__=<optimized out>)
    at /build/buildd/openjdk-7-7u71-2.5.3/build/openjdk/hotspot/src/share/vm/prims/jvmtiImpl.cpp:87
#16 0x00007f924e44eba0 in JavaThread::thread_main_inner (this=this@entry=0x7f92480bf800)
    at /build/buildd/openjdk-7-7u71-2.5.3/build/openjdk/hotspot/src/share/vm/runtime/thread.cpp:1687
#17 0x00007f924e44ee11 in JavaThread::run (this=0x7f92480bf800) at /build/buildd/openjdk-7-7u71-2.5.3/build/openjdk/hotspot/src/share/vm/runtime/thread.cpp:1667
#18 0x00007f924e313ac2 in java_start (thread=0x7f92480bf800) at /build/buildd/openjdk-7-7u71-2.5.3/build/openjdk/hotspot/src/os/linux/vm/os_linux.cpp:906
#19 0x00007f924eb70182 in start_thread (arg=0x7f923e141700) at pthread_create.c:312
#20 0x00007f924f084fbd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

(gdb) frame 10
#10 Profiler::lookupFrameInformation (frame=..., jvmti=0x7f9248004630, logWriter=...) at /home/jara/devel/oss/honest-profiler/src/main/cpp/profiler.cpp:47
47      error = jvmti->GetMethodName(frame.method_id, methodName.GetRef(), NULL, NULL);
(gdb) info locals
methodName = {jvmti_ = 0x7f9248004630, ref_ = 0x0}
error = <optimized out>
declaring_class = 0x27
signature_ptr2 = {jvmti_ = 0x7f92480beef0, ref_ = 0x7f924c8dcb40 "\330\301\367"}
fileName = <optimized out>
source_name_ptr = {jvmti_ = 0x7f923e140cd0, ref_ = 0x7f924cae44f5 <LogWriter::inspectMethod(long, JVMPI_CallFrame const&)+293> "\353\250\220\017\037\204"}
file_unknown = "UnknownFile"
(gdb) print frame
$1 = (const JVMPI_CallFrame &) @0x7f923e140ce0: {lineno = 0, method_id = 0x7f0000000000}

0x7f0000000000 is suspiciously nice number.

[RajivSignal]

Could #76 be related?

[nitsanw]

Given the lack of versioning this is a bit of difficult bug to match with repository state. Can one of the reporters reproduce the issue with a recent build and report back with the 'version' they used (i.e. the repository last commit checksum)?

[ceeaspb]

@nitsanw there have been some more jvm fixes since my initial crash report (based on searching for checked_resolve_jmethod_id crashes) and @RichardWarburton 's review of related jvm bugs in 2014.

https://bugs.openjdk.java.net/browse/JDK-8147451
https://bugs.openjdk.java.net/browse/JDK-8149743
https://bugs.openjdk.java.net/browse/JDK-8152079

The comments seem to point in the direction of a high enough volume of classes and methods to provoke method unloading (which would have been the case with my workload I think being scala) triggering bugs in method lookup in the jvm. At least that would be one avenue to investigate a reproducer program that provokes method unloading to profile on different jdks (pre/post fixes).