crash in JvmtiExport::post_compiled_method_load
serguei.spitsyn at oracle.com
serguei.spitsyn at oracle.com
Wed May 9 08:33:26 UTC 2018
Hi Chris,
Thank you for sharing your thoughts!
Thanks,
Serguei
On 5/9/18 01:14, Chris Plummer wrote:
> I should have checked for new emails before posting my response. Yours
> has a lot more detail. :)
>
> Chris
>
> On 5/9/18 1:02 AM, serguei.spitsyn at oracle.com wrote:
>> 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