Open ceeaspb opened 10 years ago
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.
Also, which JDK version were you using when this crash happened? Just pasting the output of:
java -version
gives the information needed.
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...
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.
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
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.
Sorry - I should have clarified in the previous comment that obviously this is still a serious bug which I am investigating.
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.
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.
Could #76 be related?
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)?
@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).
no core dump but in