crash in JvmtiExport::post_compiled_method_load
serguei.spitsyn at oracle.com
serguei.spitsyn at oracle.com
Wed May 9 08:02:32 UTC 2018
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 at 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.spitsyn at 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.spitsyn at oracle.com
>>>> <mailto:serguei.spitsyn at oracle.com> <serguei.spitsyn at oracle.com
>>>> <mailto:serguei.spitsyn at 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
>>>>>
>>>>
>>>>
>>>
>>
More information about the serviceability-dev
mailing list