Increased safepoint cleanup tasks in Java 11 (vs 8)
Daniel D. Daugherty
daniel.daugherty at oracle.com
Tue Jun 18 19:56:07 UTC 2019
On 6/12/19 4:42 PM, Vitaly Davidovich wrote:
>
>
> On Wed, Jun 12, 2019 at 12:46 PM Vitaly Davidovich <vitalyd at gmail.com
> <mailto:vitalyd at gmail.com>> wrote:
>
>
>
> On Thu, Jun 6, 2019 at 10:29 AM Daniel D. Daugherty
> <daniel.daugherty at oracle.com <mailto:daniel.daugherty at oracle.com>>
> wrote:
>
> On 6/6/19 10:08 AM, Vitaly Davidovich wrote:
>>
>>
>> On Wed, Jun 5, 2019 at 10:13 PM Vitaly Davidovich
>> <vitalyd at gmail.com <mailto:vitalyd at gmail.com>> wrote:
>>
>>
>>
>> On Wed, Jun 5, 2019 at 7:37 PM Vitaly Davidovich
>> <vitalyd at gmail.com <mailto:vitalyd at gmail.com>> wrote:
>>
>>
>>
>> On Wed, Jun 5, 2019 at 7:10 PM Daniel D. Daugherty
>> <daniel.daugherty at oracle.com
>> <mailto:daniel.daugherty at oracle.com>> wrote:
>>
>> On 6/5/19 7:03 PM, Vitaly Davidovich wrote:
>>>
>>>
>>> On Wed, Jun 5, 2019 at 6:55 PM David Holmes
>>> <david.holmes at oracle.com
>>> <mailto:david.holmes at oracle.com>> wrote:
>>>
>>> On 6/06/2019 2:31 am, Vitaly Davidovich wrote:
>>> > On Wed, Jun 5, 2019 at 12:15 PM Daniel D.
>>> Daugherty <
>>> > daniel.daugherty at oracle.com
>>> <mailto:daniel.daugherty at oracle.com>> wrote:
>>> >
>>> >> On 6/5/19 12:04 PM, Vitaly Davidovich wrote:
>>> >>
>>> >>
>>> >>
>>> >> On Wed, Jun 5, 2019 at 11:44 AM Daniel D.
>>> Daugherty <
>>> >> daniel.daugherty at oracle.com
>>> <mailto:daniel.daugherty at oracle.com>> wrote:
>>> >>
>>> >>> On 6/5/19 11:37 AM, Vitaly Davidovich wrote:
>>> >>>> On Wed, Jun 5, 2019 at 8:58 AM Vitaly
>>> Davidovich <vitalyd at gmail.com
>>> <mailto:vitalyd at gmail.com>>
>>> >>> wrote:
>>> >>>>
>>> >>>>> Hey Aleksey,
>>> >>>>>
>>> >>>>> On Wed, Jun 5, 2019 at 8:52 AM Aleksey
>>> Shipilev <shade at redhat.com
>>> <mailto:shade at redhat.com>>
>>> >>> wrote:
>>> >>>>>
>>> >>>>>> On 6/5/19 2:33 PM, Vitaly Davidovich
>>> wrote:
>>> >>>>>>> Does anyone have ideas on
>>> pinpointing this further?
>>> >>>>>> I have the educated guess:
>>> >>>>>>
>>> https://bugs.openjdk.java.net/browse/JDK-8181859
>>> >>>>>>
>>> >>>>>> Which means you can try if
>>> -XX:MonitorUsedDeflationThreshold=0 reduces
>>> >>>>>> the number of "guaranteed"
>>> >>>>>> safepoints.
>>> >>>>>>
>>> >>>>> Hmm, the application doesn't use JVM
>>> monitors (in any meaningful
>>> >>>>> capacity). But interesting JBS entry
>>> - I will try it out, thanks! The
>>> >>>>> description of safepoint clean up in
>>> there is/was consistent with my
>>> >>>>> understanding as well. On Java 8,
>>> we'd see the "no vm operation"
>>> >>> safepoint
>>> >>>>> operations, and I always assumed it
>>> was IC buffer cleaning (even had a
>>> >>> mail
>>> >>>>> thread on that topic a few years ago,
>>> either on this list or
>>> >>>>> hotspot-compiler). That tended to
>>> stabilize (i.e. they went away)
>>> >>> after
>>> >>>>> the application reached steady state,
>>> whereas I'm seeing essentially
>>> >>>>> non-stop safepoint cleanups on 11.
>>> >>>>>
>>> >>>> Ok, adding
>>> -XX:MonitorUsedDeflationThreshold=0 seems to
>>> alleviate the
>>> >>> issue
>>> >>>> - # of entered safepoint cleanups looks
>>> on par with Java 8, although I'm
>>> >>>> still assessing a bit more.
>>> >>>
>>> >>> This observation doesn't really match
>>> with your earlier comment:
>>> >>>
>>> >>>> Hmm, the application doesn't use JVM
>>> monitors (in any meaningful
>>> >>>> capacity).
>>> >>>
>>> >>> The default value for
>>> MonitorUsedDeflationThreshold is 90. So a
>>> cleanup
>>> >>> safepoint should only be triggered if
>>> monitor use exceeds 90% of the
>>> >>> monitor pool.
>>> >>>
>>> >> Hmm, ok - I see what you mean:
>>> >>
>>> https://github.com/openjdk/jdk11u/blob/d46b56eb81b07b452141c7dcd078d33fc8e49d63/src/hotspot/share/runtime/safepoint.cpp#L604
>>> >>
>>> >> So there's either monitor usage that I'm
>>> not aware of (or forgot about) or
>>> >> the ratio is > 90 but the absolute # of
>>> them is small (which I'd consider
>>> >> "don't use in any meaningful capacity").
>>> Is there a way to print out
>>> >> monitor population so I can see?
>>> >>
>>> >>
>>> >> I've been adding a lot of logging support
>>> to the Java Monitor subsystem,
>>> >> but those changes are in JDK13 and not in
>>> JDK11. I'm trying to remember
>>> >> what there is in JDK11, but ...
>>> >>
>>> > Yeah, I'm having a hard time keeping track
>>> of what features/changes are in
>>> > what Java release or update version or
>>> upstream/downstream backport or ...
>>> >
>>> > By the way, do JNI (specifically, Java
>>> calling into native) calls cause
>>> > monitor inflation? The app in question
>>> does have substantial JNI usage. I
>>> > guess by not using java monitors
>>> extensively, I meant the vanilla flavor of
>>> > Java code with synchronized blocks/methods.
>>>
>>> JNI calls do not in themselves impact
>>> monitors. However if native code
>>> uses the JNI MonitorEnter then that does
>>> trigger inflation.
>>>
>>> David
>>> -----
>>>
>>> Thanks for clarifying, David.
>>>
>>> Pretty certain that JNI code I have is not
>>> calling MonitorEnter, but will double check.
>>>
>>> So beyond monitor contention via vanilla Java
>>> code, are there other scenarios resulting in
>>> inflation? Is there perhaps a list of these that
>>> someone could point to? I can spelunk through
>>> hotspot code, but maybe someone can spare me
>>> that exercise :).
>>
>> Java Monitor inflation is caused by:
>>
>> - contention on the same monitor between 2 or
>> more threads
>> - monitor.wait() call
>> - synchronized (obj) { obj.hashCode(); }
>>
>> The last one is specific to the HotSpot VM.
>>
>> Dan
>>
>> Awesome, thanks Dan! In lieu of more precise monitor
>> usage logging in 11, I’ll look at our code for these.
>>
>> I’m going to try "monitorinflation=debug" tomorrow:
>> https://github.com/openjdk/jdk11u/blob/737d8437886ad97c6ed21a25b9911c10b3886f61/src/hotspot/share/runtime/synchronizer.cpp#L1519
>>
>> Maybe that’ll help shed light on inflations.
>>
>> So it doesn't look like there's much monitor inflation - some
>> early during startup, but they go away fairly quickly (if
>> monitorinflation=debug is to be trusted comprehensive).
>
> Yes the 'monitorinflation=debug' logging in JDK11u will tell
> you about
> every inflation and deflation of an ObjectMonitor. It is
> rather verbose
> if you have a lot of ObjectMonitor inflation/deflation
> happening. If it
> is not overloading you with information, then monitor
> deflation is not
> your issue.
>
> So have been playing around with 'monitorinflation=debug' in
> conjunction with -XX:MonitorUsedDeflationThreshold=0. One (so
> far) puzzling observation is with the UL flag set, I still see
> recurring safepoint cleanups but no trace of monitor
> inflation/deflation events. Naively, I'd expect to see (at least)
> inflation events if a subsequent safepoint cleanup is entered for
> deflations.
>
> Dan, is it possible that monitor scavenging doesn't actually scavenge
> anything, MonitorUsedDeflationThreshold stays above 90, and then we
> enter constant safepoint cleanup phases that don't make any/enough
> progress (in terms of getting the used monitor population under that
> threshold)?
That is really interesting theory!! And I think it is an entirely plausible
explanation for what you've reported.
So if you have a thread that causes N objects to be inflated and then stops
causing inflations, if N is greater than 90% of the total ObjectMonitor
population, then you'll see a cleanup safepoint. If that cleanup safepoint
cannot deflate any of the N monitors, then during the next trigger check,
you'll see another cleanup safepoint. Lather, rinse, repeat.
> Unfortunately, various diagnostic knobs (e.g.
> ObjectMonitor::Knob_Verbose) aren't actually tunable by product users,
> nor is there any way to print out
> gMonitorFreeCount/gMonitorPopulation. So I can't say whether the
> above appears to be happening or not. But maybe you (or others on the
> list) have seen something like this.
As I said before, my recent updates to monitorinflation logging are in
JDK13.
They have not been backported (by me anyway) to anything earlier.
I have not seen the behavior you reported before and I don't think I've
seen a bug report on that behavior either.
> Also, inspection of java 8 vs 11 code does suggest that setting
> MonitorUsedDeflationThreshold=0 reverts to Java 8 behavior, at least
> in terms of gating safepoint cleanup. I may have to go with that for now.
Yup. That sounds like the right work around.
I'm going to poke around a bit more...
Dan
>
> Thanks
>
>
> Setting MonitorUsedDeflationThreshold=0 does stop the cleanup
> storm, however. So unless there's some inflation that is not
> reported via UL, it's not clear why there's this seeming disconnect.
>
>
> Just FYI: in JDK13 that particular set of diagnostics have
> moved from
> 'monitorinflation=debug' to 'monitorinflation=trace'.
>
> Ok, good to know - thanks for the heads up.
>
>
> Dan
>
>
>> Yet safepoints continue. Interestingly, the timing reported
>> in safepoint cleanup logging shows miniscule time spent
>> "deflating idle monitors" (e.g. 0.0000004 secs = 400 ns),
>> which I take as essentially overhead of going through that
>> codepath without actually doing much of anything. "updating
>> inline caches" is about the same (400-600 ns).
>>
>> However, "compilation policy safepoint handler" is tens of
>> micros (e.g. 30-50us). Looking at the code,
>> https://github.com/openjdk/jdk11u/blob/737d8437886ad97c6ed21a25b9911c10b3886f61/src/hotspot/share/runtime/compilationPolicy.cpp#L321,
>> it appears to be doing method invocation counter decaying.
>> That does stackwalks (the application has about 30 threads),
>> so fine - it's not very cheap. But, according to
>> https://github.com/openjdk/jdk11u/blob/master/src/hotspot/share/runtime/safepoint.cpp#L602,
>> decay itself does no gate doing cleanup operations.
>>
>> Unfortunately, it doesn't appear that I can trace ICBuffers
>> in product builds (TraceICBuffer flag isn't present), so
>> can't tell whether there's some change (vs java 8) in their
>> regard. Naively, it also seems odd that a single stub in the
>> ICBuffer would require a cleanup:
>> https://github.com/openjdk/jdk11u/blob/737d8437886ad97c6ed21a25b9911c10b3886f61/src/hotspot/share/code/icBuffer.cpp#L163.
>>
>> I'll keep investigating.
>>
>>
>> Dan, please let me know if you think this will be
>> fruitless :).
>>
>>
>> Only remaining input I’d appreciate from the list is
>> whether setting MonitorUsedDeflationThreshold=0
>> “restores” 8 behavior, or whether I’d run the risk of
>> something unfortunate as a result (again, with
>> respect to 8).
>>
>> Thanks
>>
>>
>>
>>
>>>
>>> Thanks!
>>>
>>>
>>>
>>> >
>>> >>
>>> >> Dan
>>> >>
>>> >>
>>> >>
>>> >> Thanks Dan
>>> >>
>>> >>>
>>> >>> Dan
>>> >>>
>>> >>>
>>> >>>>
>>> >>>> Of course now the trouble is this is an
>>> experimental option, and
>>> >>> enabling
>>> >>>> things like that in production raises
>>> eyebrows. Is it safe to assume,
>>> >>>> however, that setting this to 0
>>> essentially behaves like Java 8? It
>>> >>> appears
>>> >>>> so, based on that JBS Aleksey linked
>>> above. But just double checking.
>>> >>>>
>>> >>>> If that's the case, then perhaps we can
>>> overlook the experimental bit
>>> >>> and
>>> >>>> wait until this is done outside
>>> safepoints, per Robbin's email.
>>> >>>>
>>> >>>> Thanks to everyone that responded on
>>> this thread! Very helpful.
>>> >>>>
>>> >>>>>> --
>>> >>>>>> Thanks,
>>> >>>>>> -Aleksey
>>> >>>>>>
>>> >>>>>>
>>> >>>
>>> >>>
>>> >>
>>>
>>> --
>>> Sent from my phone
>>
>> --
>> Sent from my phone
>>
>> --
>> Sent from my phone
>>
>
More information about the hotspot-runtime-dev
mailing list