RFR: 8224221: add memprotect calls to event log
David Holmes
david.holmes at oracle.com
Thu May 23 09:53:00 UTC 2019
On 23/05/2019 5:45 pm, Baesken, Matthias wrote:
> 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 ?
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.
>
>> 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 .
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.
>
> 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) ?
I have no idea sorry. Best to open an issue and/or discuss this with the
compiler folk.
Cheers,
David
-----
> 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