RFR: 8224221: add memprotect calls to event log

[Baesken, Matthias]

Hello David,  thanks for your comments.

 I see no  "flooding"  of the  event log, of course a few more  events  occur but not just mprotect events are seen .
Example :

Events (20 events):
Event: 0.289 Thread 0x00007fdb501c4800 Thread added: 0x00007fdb501c4800
Event: 0.289 Protecting memory [0x00007fdb4f0ba000,0x00007fdb4f0be000] with protection modes 0
Event: 0.290 Executing VM operation: EnableBiasedLocking
Event: 0.291 Executing VM operation: EnableBiasedLocking done
Event: 0.291 loading class jdk/internal/vm/PostVMInitHook
Event: 0.291 loading class jdk/internal/vm/PostVMInitHook done
Event: 0.298 loading class Loop
Event: 0.298 loading class Loop done
Event: 0.303 loading class jdk/internal/loader/URLClassPath$FileLoader
Event: 0.303 loading class jdk/internal/loader/URLClassPath$FileLoader done
Event: 0.307 loading class jdk/internal/loader/URLClassPath$FileLoader$1
Event: 0.308 loading class jdk/internal/loader/URLClassPath$FileLoader$1 done
Event: 0.314 Thread 0x00007fdb501ce000 Thread added: 0x00007fdb501ce000
Event: 0.314 Protecting memory [0x00007fdb4eeb8000,0x00007fdb4eebc000] with protection modes 0
Event: 0.315 Executing VM operation: RevokeBias
Event: 0.315 Executing VM operation: RevokeBias done
Event: 5.357 Thread 0x0000000000a05000 Thread exited: 0x0000000000a05000
Event: 10.357 Thread 0x000000000094b000 Thread exited: 0x000000000094b000
Event: 97.213 Thread 0x000000000094b000 Thread added: 0x000000000094b000
Event: 97.213 Protecting memory [0x00007fdb4f2bc000,0x00007fdb4f2c0000] with protection modes 0

Regarding the  event   init -  routines :
I had a bit of trouble with the order of inits + usages  , so I changed back  to the  original  coding ; 
  then I had to add  checks to events.hpp / cpp   so that  I do not log  to a yet uninitialized  event infrastructure in early startup but I  think the added checks are good to have .

I adjusted  the "small nit" regarding output - good point .

Regarding the missing logs in os_bsd.cpp  you mentioned  :
I think they are bsd only and I have no machine here to test  - should I still add them and hope that it works ?


Fixed the solaris issue.

New webrev :

http://cr.openjdk.java.net/~mbaesken/webrevs/8224221.2/



Best regards, Matthias

> 
> On 21/05/2019 1:08 am, Baesken, Matthias wrote:
> > Hello,  please review  this small changeset .
> >
> > The current event log holds the last n events of various interesting
> operations.
> > It is printed in the hs_err file and helps to analyze various issues / bugs .
> >
> > I would like to add memory protection events to the current set or events
> added by calling Events::log .
> > (we had this for a long time in our  proprietary  VM and  would like to have
> it in Open JDK too )
> 
> So extra events will now be generated so you doubled the size of the
> buffer - any info on how this impacts the events that may get captured?
> How often do mprotect events happen? Might we always see 20 mprotect
> events and nothing else of interest? Just wondering (I never use this
> event stuff myself).
> 
> > Bug/webrev :
> >
> > https://bugs.openjdk.java.net/browse/JDK-8224221
> >
> > http://cr.openjdk.java.net/~mbaesken/webrevs/8224221.0/
> 
> Nit: "with protections %d" doesn't read right to me as "protection" is
> not a noun. How about "with protection modes %d" or "with protection
> bits %d"? (It would be nice if you could print a symbolic representation
> of the bits rather than just the raw value - and %x may be better than
> %d for the raw value.)
> 
> ---
> 
> src/hotspot/os/bsd/os_bsd.cpp
> 
> The log event should be using bottom and bottom+size for its range.
> 
> You didn't log these additional ::mprotect calls:
> 
> 1936   if (::mprotect(addr, size, prot) == 0) {
> 2020   return ::mprotect(addr, size, PROT_NONE) == 0;
> 
> ---
> 
> src/hotspot/os/linux/os_linux.cpp
> 
> The log event should be using bottom and bottom+size for its range.
> 
> ---
> 
> src/hotspot/os/solaris/os_solaris.cpp
> 
> There is no "size" variable, it's called "bytes".
> 
> It's odd that the Solaris polling_page routines call mprotect directly
> rather than solaris_mprotect. That gave you the opportunity to be more
> specific about logging those events on Solaris, but the other platforms
> miss out. Overall the use of mprotect/<os>_mprotect/guard_memory is a
> bit of a mess. :(
> 
> ---
> 
> src/hotspot/share/runtime/thread.cpp
> 
>   jint Threads::create_vm(JavaVMInitArgs* args, bool* canTryAgain) {
> +   eventlog_init();
> 
> You've made eventlog_init() the very first thing we now do in VM
> initialization which raises a number of issues for me:
> 
> - is everything it does actually safe to do with ZERO other VM
> initialization having occurred? I don't see how as it uses a Mutex when
> constructing EventLogBase and mutex initialization has not yet occurred!
> 
> - we will always initialize the Event logs because we won't yet have
> processed the parameters that may turn of LogEvents.
> 
> I think the initialization placement needs re-examination. When does the
> first mprotect call occur? I'd take a guess it would be for the guard
> pages of the main thread when it attaches.
>