Hi Ioi and David,
Ioi, thank you for the disassembly.
It helps for sure!
Below are 3 call sites for the nmethod::post_compiled_method_load_event():
void ciEnv::register_method(ciMethod* target, . . .) {
. . .
if (nm != NULL) {
// JVMTI -- compiled method notification (must be done outside lock)
nm->post_compiled_method_load_event(); <== !!
} else {
. . .
}
}
JVMCIEnv::CodeInstallResult JVMCIEnv::register_method(. . .) {
. . .
// JVMTI -- compiled method notification (must be done outside lock)
if (nm != NULL) {
nm->post_compiled_method_load_event(); <== !!
. . .
}
return result;
}
void AdapterHandlerLibrary::create_native_wrapper(const methodHandle&
method) {
. . .
if (nm != NULL) {
. . .
nm->post_compiled_method_load_event(); <== !!
}
}
The nmethod::post_compiled_method_load_event() creates a JvmtiDeferredEvent
compiled_load_event entry and enqueues it for the ServiceThread processing.
void nmethod::post_compiled_method_load_event() {
Method* moop = method();
HOTSPOT_COMPILED_METHOD_LOAD(
(char *) moop->klass_name()->bytes(),
moop->klass_name()->utf8_length(),
(char *) moop->name()->bytes(),
moop->name()->utf8_length(),
(char *) moop->signature()->bytes(),
moop->signature()->utf8_length(),
insts_begin(), insts_size());
if (JvmtiExport::should_post_compiled_method_load() ||
JvmtiExport::should_post_compiled_method_unload()) {
get_and_cache_jmethod_id();
}
if (JvmtiExport::should_post_compiled_method_load()) {
// Let the Service thread (which is a real Java thread) post the event
MutexLockerEx ml(Service_lock, Mutex::_no_safepoint_check_flag);
JvmtiDeferredEventQueue::enqueue(
JvmtiDeferredEvent::compiled_method_load_event(this)); <== !!
}
}
The vmtiDeferredEvent::compiled_method_load_event() below uses
nmethodLocker::lock_nmethod(nm) to protect the nmethod* nm
from being updated:
JvmtiDeferredEvent JvmtiDeferredEvent::compiled_method_load_event(
nmethod* nm) {
JvmtiDeferredEvent event = JvmtiDeferredEvent(TYPE_COMPILED_METHOD_LOAD);
event._event_data.compiled_method_load =
nm; <== !!
// Keep the nmethod alive until the ServiceThread can process
// this deferred event.
nmethodLocker::lock_nmethod(nm); <== !!
return event;
}
void JvmtiDeferredEventQueue::enqueue(const JvmtiDeferredEvent& event) {
assert(Service_lock->owned_by_self(), "Must own Service_lock");
process_pending_events();
// Events get added to the end of the queue (and are pulled off the
front).
QueueNode* node = new QueueNode(event);
if (_queue_tail == NULL) {
_queue_tail = _queue_head = node;
} else {
assert(_queue_tail->next() == NULL, "Must be the last element in
the list");
_queue_tail->set_next(node);
_queue_tail = node;
}
Service_lock->notify_all();
assert((_queue_head == NULL) == (_queue_tail == NULL),
"Inconsistent queue markers");
}
JvmtiDeferredEvent JvmtiDeferredEventQueue::dequeue() {
assert(Service_lock->owned_by_self(), "Must own Service_lock");
process_pending_events();
assert(_queue_head != NULL, "Nothing to dequeue");
if (_queue_head == NULL) {
// Just in case this happens in product; it shouldn't but let's not
crash
return JvmtiDeferredEvent();
}
QueueNode* node = _queue_head;
_queue_head = _queue_head->next();
if (_queue_head == NULL) {
_queue_tail = NULL;
}
assert((_queue_head == NULL) == (_queue_tail == NULL),
"Inconsistent queue markers");
JvmtiDeferredEvent event = node->event();
delete node;
return event;
}
The ServiceThread (different thread which is a JavaThread)
takes the event from the JvmtiDeferredEventQueue queue
and posts it.
void ServiceThread::service_thread_entry(JavaThread* jt, TRAPS) {
. . .
if (has_jvmti_events) {
jvmti_event = JvmtiDeferredEventQueue::dequeue(); <== !!
}
}
if (has_jvmti_events) {
jvmti_event.post(); <== !!
}
. . .
}
The JvmtiDeferredEvent::post() below makes the call:
JvmtiExport::post_compiled_method_load(nm);
and only then unlocks the nmethod nm with nmethodLocker::unlock_nmethod(nm).
void JvmtiDeferredEvent::post() {
assert(ServiceThread::is_service_thread(Thread::current()),
"Service thread must post enqueued events");
switch(_type) {
case TYPE_COMPILED_METHOD_LOAD: {
nmethod* nm = _event_data.compiled_method_load;
JvmtiExport::post_compiled_method_load(nm); <== !!
// done with the deferred event so unlock the nmethod
nmethodLocker::unlock_nmethod(nm); <== !!
break;
}
. . .
default:
ShouldNotReachHere();
}
}
The printed disassembly shows where we observe the crash in the
functions below:
void JvmtiExport::post_compiled_method_load(nmethod *nm) {
if (JvmtiEnv::get_phase() < JVMTI_PHASE_PRIMORDIAL) {
return;
}
JavaThread* thread = JavaThread::current();
EVT_TRIG_TRACE(JVMTI_EVENT_COMPILED_METHOD_LOAD,
("[%s] method compile load event triggered",
JvmtiTrace::safe_get_thread_name(thread)));
JvmtiEnvIterator it;
for (JvmtiEnv* env = it.first(); env != NULL; env = it.next(env)) {
if (env->is_enabled(JVMTI_EVENT_COMPILED_METHOD_LOAD)) {
if (env->phase() == JVMTI_PHASE_PRIMORDIAL) {
continue;
}
EVT_TRACE(JVMTI_EVENT_COMPILED_METHOD_LOAD,
("[%s] class compile method load event sent %s.%s ",
JvmtiTrace::safe_get_thread_name(thread),
(nm->method() == NULL) ? "NULL" :
nm->method()->klass_name()->as_C_string(),
(nm->method() == NULL) ? "NULL" :
nm->method()->name()->as_C_string()));
ResourceMark rm(thread);
HandleMark hm(thread);
// Add inlining information
jvmtiCompiledMethodLoadInlineRecord* inlinerecord =
create_inline_record(nm);
// Pass inlining information through the void pointer
JvmtiCompiledMethodLoadEventMark jem(thread, nm,
inlinerecord); <== !!
JvmtiJavaThreadEventTransition jet(thread);
jvmtiEventCompiledMethodLoad callback =
env->callbacks()->CompiledMethodLoad;
if (callback != NULL) {
(*callback)(env->jvmti_external(), jem.jni_methodID(),
jem.code_size(), jem.code_data(), jem.map_length(),
jem.map(), jem.compile_info());
}
}
}
}
class JvmtiCompiledMethodLoadEventMark : public JvmtiMethodEventMark {
. . .
public:
JvmtiCompiledMethodLoadEventMark(JavaThread *thread, nmethod *nm,
void* compile_info_ptr = NULL)
: JvmtiMethodEventMark(thread,methodHandle(thread,
nm->method())) { <== !!
. . .
}
. . .
}
class JvmtiMethodEventMark : public JvmtiThreadEventMark {
. . .
JvmtiMethodEventMark(JavaThread *thread, methodHandle method) :
JvmtiThreadEventMark(thread),
_mid(to_jmethodID(method))
{}; <== line 234 !!
jmethodID jni_methodID() { return _mid; }
};
All the fragments above show the code path correctly operates with nmethod
by protecting it with the nmethodLocker::lock_nmethod(nm) until the event
has been posted.
There can be several guesses about the above:
- the above is correct but some other code abuses the convention and
updates the nmethod without grabbing the nmethod lock
- the above operations with the nmethod is incorrect (miss some steps)
- some other reason (I doubt it is the case)
One conclusion is that it is unlikely an issue in the JVMTI agent as I
suspected initially.
It would still be valuable to have more details about a scenario that
reproduced this issue.
It is probably enough information to file a bug.
Any opinions on the above?
Any ideas about what can be broken?
Thanks,
Serguei
On 5/8/18 23:00, David Holmes wrote:
On 9/05/2018 3:06 PM, Ioi Lam wrote:
Serguei & Nezih,
I've looked at the crash log and it seems like nm->method() is NULL,
which caused the crash.
I am not familiar with the JVMTI internals or nmethods, so I am just
guessing here -- is it legal for nm->method() to be NULL? Or, is it
possible that someone has cleared nm->method() before it's processed
by post_compiled_method_load?
I was wondering the same thing. Vladimir K. pointed me at:
http://hg.openjdk.java.net/jdk/jdk/file/ae0ebd3cf949/src/hotspot/share/runtime/sweeper.hpp#l42
for the nmethod lifecycle. Given this is actually a deferred event, I
too wonder if the nmethod may have been made not-entrant or even
zombie, since the event was posted.
David
-----
Details from the crash log:
=================================
Native frames: (J=compiled Java code, A=aot compiled Java code,
j=interpreted, Vv=VM code, C=native code)
V [libjvm.so+0x99e365]
JvmtiExport::post_compiled_method_load(nmethod*)+0x275
V [libjvm.so+0x9a6614] JvmtiDeferredEvent::post()+0x44
V [libjvm.so+0xc2c507]
ServiceThread::service_thread_entry(JavaThread*, Thread*)+0x337
V [libjvm.so+0xceee58] JavaThread::thread_main_inner()+0xd8
V [libjvm.so+0xb6de12] thread_native_entry(Thread*)+0xf2
C [libpthread.so.0+0x7e25] start_thread+0xc5
...
R14=0x0000000000000000 is an unknown value
=================================
Here's a disassembly of JvmtiExport::post_compiled_method_load from
JDK 9.0.1
http://hg.openjdk.java.net/jdk9/jdk9/hotspot/file/b756e7a2ec33/src/share/vm/prims/jvmtiExport.cpp
2051 HandleMark hm(thread);
0x00007ffff67dd239 <+329>: mov %rax,-0x140(%rbp)
0x00007ffff67dd240 <+336>: callq 0x7ffff66149d0
<HandleMark::initialize(Thread*)>
2054 jvmtiCompiledMethodLoadInlineRecord* inlinerecord =
create_inline_record(nm);
0x00007ffff67dd245 <+341>: mov %r12,%rdi
0x00007ffff67dd248 <+344>: callq 0x7ffff67d4090
<create_inline_record(nmethod*)>
2055 // Pass inlining information through the void pointer
2056 JvmtiCompiledMethodLoadEventMark jem(thread, nm,
inlinerecord);
0x00007ffff67dd24d <+349>: mov %rax,-0x1a8(%rbp)
0x00007ffff67dd254 <+356>: mov 0x70(%r12),%rax
0x00007ffff67dd259 <+361>: mov %rbx,-0x178(%rbp)
0x00007ffff67dd260 <+368>: test %rax,%rax
0x00007ffff67dd263 <+371>: mov %rax,-0x180(%rbp)
0x00007ffff67dd26a <+378>: je 0x7ffff67dd282
<JvmtiExport::post_compiled_method_load(nmethod*)+402>
0x00007ffff67dd26c <+380>: mov %rax,-0xa0(%rbp)
0x00007ffff67dd273 <+387>: mov 0x160(%rbx),%rdi
0x00007ffff67dd27a <+394>: mov %r13,%rsi
0x00007ffff67dd27d <+397>: callq 0x7ffff671d5f0
<GrowableArray<Metadata*>::append(Metadata* const&)>
0x00007ffff67dd282 <+402>: lea 0x218(%rbx),%rax
0x00007ffff67dd289 <+409>: mov %rbx,-0xf0(%rbp)
0x00007ffff67dd290 <+416>: movl $0x0,-0xe0(%rbp)
0x00007ffff67dd29a <+426>: mov %rax,-0xe8(%rbp)
0x00007ffff67dd2a1 <+433>: mov 0x3c8(%rbx),%rax
0x00007ffff67dd2a8 <+440>: test %rax,%rax
0x00007ffff67dd2ab <+443>: je 0x7ffff67dd2b6
<JvmtiExport::post_compiled_method_load(nmethod*)+454>
0x00007ffff67dd2ad <+445>: mov 0x10(%rax),%eax
0x00007ffff67dd2b0 <+448>: mov %eax,-0xe0(%rbp)
0x00007ffff67dd2b6 <+454>: mov 0x38(%rbx),%r14
0x00007ffff67dd2ba <+458>: mov %rbx,%rdi
0x00007ffff67dd2bd <+461>: callq 0x7ffff6707d50
<JNIHandleBlock::allocate_block(Thread*)>
0x00007ffff67dd2c2 <+466>: lea 0x1f8(%rbx),%rdi
0x00007ffff67dd2c9 <+473>: mov %rbx,%rsi
0x00007ffff67dd2cc <+476>: mov %r14,0x118(%rax)
0x00007ffff67dd2d3 <+483>: mov %rax,0x38(%rbx)
0x00007ffff67dd2d7 <+487>: callq 0x7ffff6559410
<JavaFrameAnchor::make_walkable(JavaThread*)>
0x00007ffff67dd2dc <+492>: mov 0x1f0(%rbx),%rsi
0x00007ffff67dd2e3 <+499>: mov -0xf0(%rbp),%rdi
0x00007ffff67dd2ea <+506>: callq 0x7ffff6708520
<JNIHandles::make_local(Thread*, oopDesc*)>
0x00007ffff67dd2ef <+511>: mov -0x1a0(%rbp),%rsi
0x00007ffff67dd2f6 <+518>: mov %rax,-0xd8(%rbp)
0x00007ffff67dd2fd <+525>: lea -0x170(%rbp),%rax
0x00007ffff67dd304 <+532>: mov %rax,%rdi
0x00007ffff67dd307 <+535>: mov %rax,-0x1b0(%rbp)
// JvmtiMethodEventMark(JavaThread *thread, methodHandle method) :
// JvmtiThreadEventMark(thread),
234 _mid(to_jmethodID(method)) {}; <-- this line
0x00007ffff67dd30e <+542>: callq 0x7ffff66140a0
<methodHandle::methodHandle(methodHandle const&)>
0x00007ffff67dd313 <+547>: mov -0x170(%rbp),%r14
0x00007ffff67dd31a <+554>: movq $0x0,-0x98(%rbp)
0x00007ffff67dd325 <+565>: test %r14,%r14
0x00007ffff67dd328 <+568>: mov %r14,-0xa0(%rbp)
0x00007ffff67dd32f <+575>: je 0x7ffff67dd365
<JvmtiExport::post_compiled_method_load(nmethod*)+629>
0x00007ffff67dd331 <+577>: data16 lea
0x946ca7(%rip),%rdi # 0x7ffff7123fe0
0x00007ffff67dd339 <+585>: data16 data16 callq 0x7ffff60b11d0
<__tls_get_addr@plt>
0x00007ffff67dd341 <+593>: lea -0x188(%rbp),%rsi
0x00007ffff67dd348 <+600>: mov %r14,-0x188(%rbp)
0x00007ffff67dd34f <+607>: mov (%rax),%rax
0x00007ffff67dd352 <+610>: mov %rax,-0x98(%rbp)
0x00007ffff67dd359 <+617>: mov 0x160(%rax),%rdi
0x00007ffff67dd360 <+624>: callq 0x7ffff671d5f0
<GrowableArray<Metadata*>::append(Metadata* const&)>
>>> CRASH %r14 == 0x0
198 jmethodID to_jmethodID(methodHandle method) { return
method->jmethod_id(); }
0x00007ffff67dd365 <+629>: mov 0x8(%r14),%rax
Hope this helps
- Ioi
On 5/8/18 4:51 PM, serguei.spit...@oracle.com wrote:
Hi Nezih,
Crashing in the JvmtiExport::post_compiled_method_load function
does not prove itself that it is a VM issue.
And there are mo specific details in the log that help to understand
this.
Filing a bug with this log is almost useless as it would not help to
get to the root cause.
Also, there is still a pretty big chance the real problem is in the
agent.
My advice is to get as more details about this crash as possible.
The best you can do is to provide a stand alone test case.
Even if the issue is in the agent it will help to figure it out.
Thanks,
Serguei
On 5/8/18 16:38, nezih yigitbasi wrote:
Hi Serguei,
We don't have a repro unfortunately. We have seen this only once so
far in our production environment.
Do you think this can be an agent issue? I thought like if it was
an agent issue the stack trace would show it. The stack trace,
however, ends in the VM code -- the crash happens in the
"JvmtiExport::post_compiled_method_load" method.
Thanks,
Nezih
2018-05-08 16:34 GMT-07:00 serguei.spit...@oracle.com
<mailto:serguei.spit...@oracle.com> <serguei.spit...@oracle.com
<mailto:serguei.spit...@oracle.com>>:
Hi Nezih,
You error file with log does not help much.
Could you, please, reproduce this issue with the debug or
fastdebug build?
Also, a standalone test case is better to provide to
increase chances the issue to be investigated and fixed.
In general, a JVMTI agent has to be written very carefully as it
can easily cause the VM to crash.
So, it makes sense to look at the agent implementation first to
make sure it does not do anything wrong.
It is what we normally do first and why a test case that
demonstrates the problem is needed.
Thanks,
Serguei
On 5/8/18 16:00, nezih yigitbasi wrote:
Hi,
First of all, sorry for bringing up a crash issue in this dev
mailing list, but the crash report submission page
(https://bugreport.java.com/bugreport/crash.jsp
<https://bugreport.java.com/bugreport/crash.jsp>) doesn't list
Java 9 in the release drop down, so I couldn't report it there.
We recently got a crash with Java 9.0.1+11 with an interesting
stack ending at "JvmtiExport::post_compiled_method_load()"
(entire error file is here
<https://gist.github.com/nezihyigitbasi/52a58698cc9acfcab21c69d00bd0cef2>).
A google search didn't end up with much info, so I just wanted
to check with this mailing list to see whether anyone has any
ideas to investigate this further.
Thanks,
Nezih
