RFR: 8224221: add memprotect calls to event log
Baesken, Matthias
matthias.baesken at sap.com
Thu May 23 07:45:15 UTC 2019
Hi David ,
> > Additionally I added calls to
> > bool os::guard_memory(char* addr, size_t bytes)
> > and
> > bool os::unguard_memory(char* addr, size_t bytes)
> >
> > on Windows .
>
> 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 ?
> On linux we have a split between
> use of mprotect and use of mmap and this change only logs mprotect on
> Linux; but those same semantics actions e.g. pd_commit_memory, on
> Windows use VirtualProtect.
>
> > Regarding the event log initialization - I think it is better to keep the init
> where it is for now , moving it in front of other inits just leads to asserts and
> crashes
> > so I think it is out of scope of the CR to redo the whole init process .
>
> I'm not asking you to do that. I'm asking you to determine what init
> dependencies your change actually has. If you keep the init where it is
> you may miss logging some early mprotect usages (of course there's no
> guarantee you can log them all if the init dependencies can't be resolved)
>
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/share/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 .
Btw when looking into the other already present Events::log* calls I wondered about this :
In deoptimization.cpp , there are 3 calls to Events:log, like
Events::log(thread, "DEOPT UNPACKING pc=" INTPTR_FORMAT " sp=" INTPTR_FORMAT " mode %d",
p2i(stub_frame.pc()), p2i(stub_frame.sp()), exec_mode);
But just one Events::log_deopt_message
Events::log_deopt_message(thread, "Uncommon trap: reason=%s action=%s pc=" INTPTR_FORMAT " method=%s @ %d %s",
trap_reason_name(reason), trap_action_name(action), p2i(fr.pc()),
trap_method->name_and_sig_as_C_string(), trap_bci, nm->compiler_name());
I think all 4 messages should go to the separate deoptimization - log and use Events::log_deopt_message.
Or is there a special intentation why some go into the depot-log (Events::log_deopt_message ) and some into the general events log (Events::log) ?
With the current coding you have deoptimization related logging across both ( Deoptimization events, and general Events) which looks a bit strange to me , example (see the DEOPT ... in the general Event log) :
Deoptimization events (20 events):
Event: 143.015 Thread 0x00007fffa4588800 Uncommon trap: reason=profile_predicate action=maybe_recompile pc=0x00007fff75354f08 method=sun.java2d.marlin.DHelpers$PolyStack.popAll(Lsun/java2d/marlin/DPathConsumer2D;)V @ 71 c2
Event: 143.661 Thread 0x00007fffa4588800 Uncommon trap: reason=predicate action=maybe_recompile pc=0x00007fff753be9b0 method=sun.font.ExtendedTextSourceLabel.createCharinfo()[F @ 306 c2
Event: 145.350 Thread 0x00007fffa4586800 Uncommon trap: reason=profile_predicate action=maybe_recompile pc=0x00007fff753f363c method=sun.font.ExtendedTextSourceLabel.createCharinfo()[F @ 306 c2
Event: 145.353 Thread 0x00007fffa4586800 Uncommon trap: reason=profile_predicate action=maybe_recompile pc=0x00007fff753f363c method=sun.font.ExtendedTextSourceLabel.createCharinfo()[F @ 306 c2
Event: 145.357 Thread 0x00007fffa4586800 Uncommon trap: reason=profile_predicate action=maybe_recompile pc=0x00007fff753f363c method=sun.font.ExtendedTextSourceLabel.createCharinfo()[F @ 306 c2
Event: 145.359 Thread 0x00007fffa4586800 Uncommon trap: reason=profile_predicate action=maybe_recompile pc=0x00007fff753f363c method=sun.font.ExtendedTextSourceLabel.createCharinfo()[F @ 306 c2
Event: 147.403 Thread 0x00007fffa4021000 Uncommon trap: reason=unstable_if action=reinterpret pc=0x00007fff751d8e44 method=sun.util.calendar.BaseCalendar$Date.hit(I)Z @ 5 c2
Event: 147.403 Thread 0x00007fffa4021000 Uncommon trap: reason=unstable_if action=reinterpret pc=0x00007fff7531a80c method=java.util.GregorianCalendar.getWeekNumber(JJ)I @ 48 c2
Event: 147.403 Thread 0x00007fffa4021000 Uncommon trap: reason=unstable_if action=reinterpret pc=0x00007fff752c76b4 method=java.util.Calendar.setTimeInMillis(J)V @ 6 c2
Event: 147.404 Thread 0x00007fffa4021000 Uncommon trap: reason=unstable_if action=reinterpret pc=0x00007fff750de4c4 method=java.util.GregorianCalendar.getWeekNumber(JJ)I @ 48 c2
Event: 156.024 Thread 0x00007fffa43fe000 Uncommon trap: reason=unstable_if action=reinterpret pc=0x00007fff752455e8 method=java.lang.Double.compare(DD)I @ 3 c2
Event: 158.698 Thread 0x00007fffa4586800 Uncommon trap: reason=unstable_if action=reinterpret pc=0x00007fff754e1bc8 method=java.util.HashMap.removeNode(ILjava/lang/Object;Ljava/lang/Object;ZZ)Ljava/util/HashMap$Node; @ 89 c2
Event: 175.768 Thread 0x00007fffa43fe000 Uncommon trap: reason=speculate_null_assert action=make_not_entrant pc=0x00007fff74f08890 method=sun.util.locale.LocaleObjectCache.cleanStaleEntries()V @ 12 c2
Event: 176.402 Thread 0x00007fffa43fe000 Uncommon trap: reason=unstable_if action=reinterpret pc=0x00007fff75523338 method=com.crystaldecisions.reports.dataengine.DataContext.fetchGroupPath(I)Lcom/crystaldecisions/reports/common/GroupPath; @ 35 c2
Event: 176.412 Thread 0x00007fffa43fe000 Uncommon trap: reason=range_check action=make_not_entrant pc=0x00007fff754409dc method=sun.font.ExtendedTextSourceLabel.createCharinfo()[F @ 338 c2
Event: 176.439 Thread 0x00007fffa43fe000 Uncommon trap: reason=unstable_if action=reinterpret pc=0x00007fff7550c0ec method=com.crystaldecisions.reports.dataengine.DataProcessor2.getGroupLevelFromCurrentDataPosition()I @ 17 c2
Event: 176.694 Thread 0x00007fffa43fe000 Uncommon trap: reason=profile_predicate action=maybe_recompile pc=0x00007fff7543826c method=java.awt.geom.Path2D$Double.append(Ljava/awt/geom/PathIterator;Z)V @ 11 c2
Event: 176.694 Thread 0x00007fffa43fe000 Uncommon trap: reason=profile_predicate action=maybe_recompile pc=0x00007fff7543826c method=java.awt.geom.Path2D$Double.append(Ljava/awt/geom/PathIterator;Z)V @ 11 c2
Event: 176.698 Thread 0x00007fffa43fe000 Uncommon trap: reason=profile_predicate action=maybe_recompile pc=0x00007fff7543826c method=java.awt.geom.Path2D$Double.append(Ljava/awt/geom/PathIterator;Z)V @ 11 c2
Event: 176.698 Thread 0x00007fffa43fe000 Uncommon trap: reason=profile_predicate action=maybe_recompile pc=0x00007fff7543826c method=java.awt.geom.Path2D$Double.append(Ljava/awt/geom/PathIterator;Z)V @ 11 c2
......
Events (20 events):
Event: 176.694 Thread 0x00007fffa43fe000 DEOPT UNPACKING pc=0x00007fff4c80236c sp=0x00007ffe82b9c000 mode 2
Event: 176.694 Thread 0x00007fffa43fe000 Uncommon trap: trap_request=0xffffffbe fr.pc=0x00007fff7543826c relative=0x000000000000166c
Event: 176.694 Thread 0x00007fffa43fe000 DEOPT PACKING pc=0x00007fff7543826c sp=0x00007ffe82b9c1a0
Event: 176.694 Thread 0x00007fffa43fe000 Create unroll information: #vframes=1 pc=0x00007fff7543826c sp=0x00007ffe82b9c1a0
Event: 176.694 Thread 0x00007fffa43fe000 DEOPT UNPACKING pc=0x00007fff4c80236c sp=0x00007ffe82b9c000 mode 2
Event: 176.698 Thread 0x00007fffa43fe000 Uncommon trap: trap_request=0xffffffbe fr.pc=0x00007fff7543826c relative=0x000000000000166c
Event: 176.698 Thread 0x00007fffa43fe000 DEOPT PACKING pc=0x00007fff7543826c sp=0x00007ffe82b9bf60
Event: 176.698 Thread 0x00007fffa43fe000 Create unroll information: #vframes=1 pc=0x00007fff7543826c sp=0x00007ffe82b9bf60
Event: 176.698 Thread 0x00007fffa43fe000 DEOPT UNPACKING pc=0x00007fff4c80236c sp=0x00007ffe82b9bdc0 mode 2
Event: 176.698 Thread 0x00007fffa43fe000 Uncommon trap: trap_request=0xffffffbe fr.pc=0x00007fff7543826c relative=0x000000000000166c
Event: 176.698 Thread 0x00007fffa43fe000 DEOPT PACKING pc=0x00007fff7543826c sp=0x00007ffe82b9bf80
Event: 176.698 Thread 0x00007fffa43fe000 Create unroll information: #vframes=1 pc=0x00007fff7543826c sp=0x00007ffe82b9bf80
Event: 176.698 Thread 0x00007fffa43fe000 DEOPT UNPACKING pc=0x00007fff4c80236c sp=0x00007ffe82b9bde0 mode 2
Event: 176.946 Executing VM operation: G1CollectForAllocation
Event: 176.950 begin safepoint, id: 1171
Event: 177.081 end safepoint, id: 1171
Event: 177.081 Executing VM operation: G1CollectForAllocation done
Event: 177.235 Executing VM operation: G1CollectForAllocation
Event: 177.236 begin safepoint, id: 1173
Event: 177.408 Protecting memory [0x00007fffac240000,0x00007fffac250000] with protection modes 7
Best regards, Matthias
More information about the hotspot-dev
mailing list