RFR: 8224221: add memprotect calls to event log

[David Holmes]

Hi Matthias,

On 23/05/2019 11:25 pm, Baesken, Matthias wrote:
>>>>
>>>> This is starting to look a bit inconsistent. If you want to log
>>>> VirtualProtect calls then there are more of them than just in
>>>> guard_memory and unguard_memory. So I'm unclear on the intent here -
>> is
>>>> it to log all "memory protection" actions or only to log those that
>>>> pertain to specific semantic actions?
>>>
>>> My Intention was to cover Windows as well,  however  it looks like  there
>> are more  VirtualProtect calls  (9)   in  os_windows.cpp   than  mprotects  in
>> os_linux.cpp  (just 1 in linux_mprotect).
>>> But maybe it is better to  omit VirtualProtect /   os_windows in this patch ,
>> no problem.
>>> What do you think ?
>>
>> I think you need to decide what this work is trying to log - is it
>> "mprotect" calls or is it "memory protection" calls? Or something else.
> 
> Hi David,
> 
> Let's  concentrate on the mprotects    !
> 
> http://cr.openjdk.java.net/~mbaesken/webrevs/8224221.4/

Okay so basically non-Windows support. Please make this clear in the bug 
report.

Those changes seem fine.

>>>
>>> Yes ,  if I keep  the   eventlog_init()   where it is, I miss  a few  early
>> mprotect  calls .
>>> I observed this in our tests .
>>>
>>> However  when  moving forward  eventlog_init  like I did in the first rev.   (
>> http://cr.openjdk.java.net/~mbaesken/webrevs/8224221.0/src/hotspot/sha
>> re/runtime/thread.cpp.frames.html  ) ,
>>> I run into   " assert(os::mutex_init_done()) failed: Too early! "
>>> Mutex_init is done in   os::init_2 , which is  called from
>>>
>>> Threads::create_vm() {
>>>      ...
>>> 3740   // Initialize the os module after parsing the args
>>> 3741   jint os_init_2_result = os::init_2();
>>> 3742   if (os_init_2_result != JNI_OK) return os_init_2_result;
>>>     ...
>>> }
>>>
>>> So  I could  place  eventlog_init()   after   os::init_2  instead of the start of
>> Threads::create_vm .
>>
>> I added an assert(false) in linux_mprotect to see where it is first
>> called from (not 100% accurate as different flags may trigger other code
>> paths) and found it was called from initialize_assert_poison() here:
>>
>>     // Initialize the os module after parsing the args
>>     jint os_init_2_result = os::init_2();
>>     if (os_init_2_result != JNI_OK) return os_init_2_result;
>>
>> #ifdef CAN_SHOW_REGISTERS_ON_ASSERT
>>     // Initialize assert poison page mechanism.
>>     if (ShowRegistersOnAssert) {
>>       initialize_assert_poison();
>>     }
>> #endif // CAN_SHOW_REGISTERS_ON_ASSERT
>>
>> So if you move your event_init to before the #ifdef it not only should
>> work okay, but it also shouldn't normally miss any calls to mprotect.
>> Obviously more extensive testing would be needed.
>>
> 
> Thanks for looking into it .
> Unfortunately this causes another assertion  (shows up already in the fastdebug  build  when using  the new JVM) .
> 
> 
> jdk/src/hotspot/share/runtime/thread.hpp:818), pid=53146, tid=53268
> assert(current != __null) failed: Thread::current() called on detached thread

Okay so that's a different problem: the event log uses a mutex and that 
needs an attached thread. So you can't use the event_log before the main 
thread has attached even if you've initialized the event log. So even if 
you keep the eventlog_init() where it is inside vm_init_globals(), 
there's a small risk you could still try to use the event log before the 
main thread attaches:

   // Initialize global data structures and create system classes in heap
   vm_init_globals();

#if INCLUDE_JVMCI
   if (JVMCICounterSize > 0) {
     JavaThread::_jvmci_old_thread_counters = NEW_C_HEAP_ARRAY(jlong, 
JVMCICounterSize, mtInternal);
     memset(JavaThread::_jvmci_old_thread_counters, 0, sizeof(jlong) * 
JVMCICounterSize);
   } else {
     JavaThread::_jvmci_old_thread_counters = NULL;
   }
#endif // INCLUDE_JVMCI

   // Attach the main thread to this os thread
   JavaThread* main_thread = new JavaThread();
   main_thread->set_thread_state(_thread_in_vm);
   main_thread->initialize_thread_current();
   // must do this before set_active_handles
   main_thread->record_stack_base_and_size();
   main_thread->register_thread_stack_with_NMT();
   main_thread->set_active_handles(JNIHandleBlock::allocate_block());

   if (!main_thread->set_as_starting_thread()) {
     vm_shutdown_during_initialization(
                                       "Failed necessary internal 
allocation. Out of swap space");
     main_thread->smr_delete();
     *canTryAgain = false; // don't let caller call JNI_CreateJavaVM again
     return JNI_ENOMEM;
   }

   // Enable guard page *after* os::create_main_thread(), otherwise it would
   // crash Linux VM, see notes in os_linux.cpp.
   main_thread->create_stack_guard_pages();

Fortunately the sequence of mprotect calls seems to be:
- initialize_assert_poison() (if enabled and a debug build)
- two via SafepointMechanism::initialize();
- main_thread->create_stack_guard_pages();  (around 10 calls in here)

So it appears that currently leaving the eventlog_init() where it is, 
and ensuring you don't log before initialization, that things will work 
okay. I have some reservations about what may be possible if the main 
thread takes a lock etc before its guard pages have been set up - but I 
think that should be safe. There may also be an issue if we take the 
vm_exit path - but as of now there are no mprotect calls if we do that.

David
-----

> V  [libjvm.so+0x18d000f]  VMError::report_and_die(Thread*, void*, char const*, int, char const*, char const*, __va_list_tag*)+0x2f
> V  [libjvm.so+0xa7f051]  report_vm_error(char const*, int, char const*, char const*, ...)+0x111
> V  [libjvm.so+0x136e04e]  Monitor::lock_without_safepoint_check()+0x1be
> V  [libjvm.so+0xaacf07]  Events::log(Thread*, char const*, ...)+0xe7
> V  [libjvm.so+0x140c18b]  linux_mprotect(char*, unsigned long, int)+0x12b
> V  [libjvm.so+0xa84197]  initialize_assert_poison()+0xc7
> V  [libjvm.so+0x1810322]  Threads::create_vm(JavaVMInitArgs*, bool*)+0x2b2
> V  [libjvm.so+0xf07b59]  JNI_CreateJavaVM+0x69
> C  [libjli.so+0x42b6]  JavaMain+0x86
> C  [libjli.so+0x8319]  ThreadJavaMain+0x9
> 
> Best regards, Matthias
>