RFR(S): 8223575: add subspace transitions to gc+metaspace=info log lines

Wed Jun 5 05:58:05 UTC 2019

Hi Tony,

looks good overall. Minor nits:

I do not like the getting-values-in-ctor for MetaspaceSizesSnapshot - it
conflicts with how the rest of the data are queried in
G1HeapTransition::Data::Data.

One has to examine the ctor for MetaspaceSizesSnapshot to realize that we
did not just simply forget querying the sizes.

I would prefer a dumb structure getting filled by a metaspace function. Or,
give MetaspaceSizesSnapshot a "::fill()" or "::query_with_current_values()"
function which can be called explicitly from within
G1HeapTransition::Data::Data().

This is aesthetics. I leave it up to you resp. wait for the second
reviewers opinion.

--

MetaspaceSizesSnapshot:

Can you rename all members named "capacity" to "committed"? In Metaspace,
capacity refers to the sum of in-use chunks and does not contain the free
chunks.

(capacity = used + free + waste/overhead for in-use chunks. Committed =
capacity + free chunks + some other small overheads.)

--

While you are at it, could you please rename
MetaspaceUtils::print_metaspace_change to
MetaspaceUtils::log_metaspace_change since print_.. is usually the name of
printing functions which take an outputStream*. log_.. () is usually used
for functions printing to UL or EventLog, so that would be a clearer name.

Also could you please make a small addition to the comment in metaspace.hpp:

-   // Print change in used metadata.
+   // Print change in used metadata (for GC logging).

--

I am not sure if this needs a CSR and/or a Release Note since we change the
format of the Metaspace entgc log entries and that may confuse people. If
it does, I can review the CSR for you and hopefully it goes fast. I wait
for the second reviewers opinion on this (preferably someone from Oracles
GC group).

Cheers, Thomas

On Tue, Jun 4, 2019 at 9:37 PM Tony Printezis <tprintezis at twitter.com>
wrote:

> Hi Thomas,
>
> Thanks for the suggestions. Here’s a new webrev:
>
> http://cr.openjdk.java.net/~tonyp/8223575/webrev.2/
>
> I renamed the spaces as discussed, added the before capacity to the
> output, and use the committed size, instead of the reserved size, for
> capacity. The output now looks like this:
>
> [31.167s][info][gc,metaspace ] GC(27) Metaspace:
> 2120K(5504K)->2120K(5504K) NonClass: 1898K(4864K)->1898K(4864K) Class:
> 221K(640K)->221K(640K)
>
> One more minor change: MetaspaceUtils::print_metaspace_change(…) now gets
> the “after” values using a MetaspaceSizesSnapshot object instead of calling
> methods directly (which I think is a bit nicer).
>
> I'd like to add a Twitter copyright to the two new files. But I’m waiting
> to hear from the “higher ups” about that. I left two TODOs about that in
> the metaspaceSizesSnapshot.{hpp,cpp} files so I don’t forget. Please ignore
> those for now… I’ll remove them before pushing.
>
> Tony
>
> —————
> Tony Printezis | @TonyPrintezis | tprintezis at twitter.com
>
>
> On May 15, 2019 at 4:26:17 AM, Thomas Stüfe (thomas.stuefe at gmail.com)
> wrote:
>
> Hi Tony,
>
> I combine my answer to both your mails up into this one mail:
>
> - I am fine with printing "used" and "committed" and leaving out
> "reserved".
> - Choose whatever format you like, I like them all :)
>
> more inline:
>
> On Wed, May 15, 2019 at 10:15 AM Tony Printezis <tprintezis at twitter.com>
> wrote:
>
>> Thomas,
>>
>> Yeah, I’ll update the space names as discussed in the previous e-mail and
>> rework the size transition format (unless I hear otherwise!).
>>
>> Re: I generally use references for const arguments and pointers for
>> arguments the method modifies (to make it a bit clearer what will be
>> modified and what it will not).
>>
>
> Yes, I prefer that too.
>
>
>>
>> Quick related question: I saw that some files seem to have SAP (and also
>> RedHat?) copyright notices in addition to the usual Oracle ones. So, I can
>> add a Twitter copyright line for any new files we add?
>>
>
> I usually add SAP copyrights for files I introduce and which have a
> reasonable large original content made by us.
>
>
>>
>> I’m on vacation this week and next, so it might be a few days before I
>> post a new webrev. Thanks again for the comments!
>>
>
> Np. Enjoy your time off.
>
> Cheers, Thomas
>
>
>>
>> Tony
>>
>>
>> —————
>> Tony Printezis | @TonyPrintezis | tprintezis at twitter.com
>>
>>
>> On May 13, 2019 at 7:50:44 PM, Thomas Stüfe (thomas.stuefe at gmail.com)
>> wrote:
>>
>> Hi Tony,
>>
>> had a look at your second webrev. Seems fine, modulo the discussion
>> points from my mail from earlier today.
>>
>> Small nit, I personally prefer pointers vs references for output
>> structures, but I leave it up to you whether you want to change it.
>>
>> Cheers, Thomas
>>
>> On Thu, May 9, 2019 at 10:00 PM Tony Printezis <tprintezis at twitter.com>
>> wrote:
>>
>>> Thomas,
>>>
>>> Updated webrev:
>>>
>>> http://cr.openjdk.java.net/~tonyp/8223575/webrev.1/
>>>
>>> with some of the suggested changes:
>>>
>>> * did some renaming
>>> * created hpp / cpp files for the new class (now called
>>> MetaspaceSizesSnapshot)
>>> * moved the formatting macros to globalDefinitions.hpp
>>>
>>> Still pending:
>>>
>>> * What should we call the spaces?
>>> * Should we add the before capacity in the output?
>>>
>>> (let me know if I missed anything…)
>>>
>>> Tony
>>>
>>>
>>> —————
>>> Tony Printezis | @TonyPrintezis | tprintezis at twitter.com
>>>
>>>
>>> On May 9, 2019 at 12:38:35 PM, Tony Printezis (tprintezis at twitter.com)
>>> wrote:
>>>
>>> Hi Thomas,
>>>
>>> Thanks for the detailed feedback and suggestions. Please see inline….
>>>
>>>
>>> —————
>>> Tony Printezis | @TonyPrintezis | tprintezis at twitter.com
>>>
>>>
>>> On May 8, 2019 at 4:07:49 PM, Thomas Stüfe (thomas.stuefe at gmail.com)
>>> wrote:
>>>
>>>
>>> Hi Tony,
>>>
>>> I think this makes sense. I agree, the output as it is now can be
>>> confusing. Note that users can still be confused since users may simply not
>>> be aware that the default ClassSpace reserved size is 1G.
>>>
>>>
>>> Yes. What a user wants to size is (what I call - more below) the class
>>> metadata space. But, in the log, this is hidden in the total size. So, this
>>> creates confusion. FWIW, the older +PrintHeapAtGC output had the same issue:
>>>
>>>  Metaspace       used 5660K, capacity 5996K, committed 6144K, reserved
>>> 1056768K
>>>
>>>   class space    used 630K, capacity 734K, committed 768K, reserved
>>> 1048576K
>>>
>>> It shows the total size and the class space size (which the user might
>>> not know what it is) but doesn’t explicitly show the space the user
>>> actually wants to size.
>>>
>>> I think we can make it a bit easier for them.
>>>
>>>
>>>
>>> Can your change break scripts for folks parsing GC logs? I see that you
>>> only appended content and did not change the existing text, so I guess this
>>> is okay.
>>>
>>>
>>> Of course the change can break a GC log parsing script, if it assumes
>>> there’s only one size transition on gc,metaspace lines (but if it just
>>> parses the size transition and ignores that rest it will still work). But
>>> is there a hard requirement that we cannot change any log output? That’d be
>>> unfortunate, IMHO. In fact, the safepoint=info output changed almost
>>> totally between 11 and now.
>>>
>>> 11:
>>>
>>> [49.768s][info ][safepoint        ] Entering safepoint region: Cleanup
>>>
>>> ...
>>>
>>> [49.769s][info ][safepoint        ] Total time for which application
>>> threads were stopped: 0.0005466 seconds, Stopping threads took: 0.0001931
>>> seconds
>>>
>>> now:
>>>
>>> [880.754s][info ][safepoint        ] Safepoint
>>> "GenCollectForAllocation", Time since last: 990253904 ns, Reaching
>>> safepoint: 440316 ns, At safepoint: 3761268 ns, Total: 4201584 ns
>>>
>>>
>>>
>>> ---
>>>
>>> Format and naming: Different forms are used in different places. In
>>> hs-err files, we print "Metaspace" and "Class Space", with the former being
>>> the total sum and the latter the class space part.
>>>
>>> But in other corners, eg. in the jcmd VM.metaspace command, we print
>>> non-class space and class space and maybe the sum in addition. Usually
>>> non-class space is called "Non-Class".
>>>
>>> I personally would prefer, in this case, the latter names: "Class Space"
>>> and "Non-Class Space"
>>>
>>>
>>> Here’s another pet-peeve of mine (and I’m probably overthinking this)
>>> :-) : Users know that the metaspace holds class metadata. So, calling the
>>> area that actually holds the class metadata “Non-Class Space” and the area
>>> that holds some internal JVM data structure “Class Space” is
>>> counter-productive and confusing (IMHO). We don’t have to use the names I
>>> used. But any chance of coming up with something less confusing?
>>>
>>>
>>>
>>> ---
>>>
>>> Note that for non-class space, reserved size can actually change when
>>> allocating and releasing metaspace, if VirtualSpaceNodes get purged or
>>> newly allocated. Hence total reserved size can change too. So we may want
>>> to print out reserved before and reserved after sizes. I guess that was
>>> also missing from the output before.
>>>
>>>
>>> I’ll be very happy to add the before capacity to the output. You mean
>>> something like this, right?
>>>
>>> 2300K(4192K)->2100K(4192K)
>>>
>>> And we should also add it to the heap size transitions too, as they have
>>> the same issue (the heap can be resized during a GC). Of course, this will
>>> definitely require GC log parser changes. :-) But I think the change is
>>> worthwhile. Any objections?
>>>
>>>
>>>
>>> ----
>>>
>>> Since used = class used + nonclass used, I would simplify
>>> PreMetaspaceValues to _non_class_used and _class_used and calculate the sum
>>> on the fly.
>>>
>>>
>>> Yeah, I thought about that. I just decided to just store the total used
>>> to avoid replicating the logic of how that’s calculated in that class too.
>>>
>>>
>>>
>>> ---
>>>
>>> You added a new dependency to heap.hpp into metaspace.cpp for the format
>>> string. Is this really necessary? Can you move this define to metaspace.cpp?
>>>
>>> If not, you need at least add include heap.hpp (did it build this way
>>> without precompiled headers?)
>>>
>>>
>>> I didn’t try to explicitly compile without precompiled headers. jdk
>>> submit job was successful. Is that usually evidence enough? If not, I’ll
>>> need to add the extra step to my workflow.
>>>
>>> As I eluded to earlier, if this change is accepted I’m going to suggest
>>> to also expand the gc,heap output with sub-space information for the young
>>> gen (eden  / survivors). So I wanted to move the FORMAT macros to somewhere
>>> that can also be shared by GC files. I was not sure if heap.hpp was the
>>> best place for them. Maybe I can just put them in globalDefinitions.hpp, as
>>> there’s already some size formatting utilities there
>>> (proper_unit_for_byte_size(…), etc.)?
>>>
>>>
>>>
>>> ----
>>>
>>> The following issues are matters of taste, and I leave it up to you
>>> whether you want to change something:
>>>
>>> -> I wince a bit at yet another metaspace-sizes-structure - we have
>>> already ClassLoaderMetaspaceStatistics and MetaspaceCounters, and maybe
>>> others. JFR may also do something similar. Would it be possible to reuse
>>> one of those? (I guess ClassLoaderMetaspaceStatistics is too fine granular
>>> and too expensive to collect.)
>>>
>>>
>>> I was not aware of the two you mentioned. Aren’t MetaspaceCounters only
>>> available when UsePerfData is enabled? I’d rather decouple this from
>>> UsePerfData. ClassLoaderMetaspaceStatistics does seem too fine-grain for
>>> what I want. And I modeled PreMetaspaceValues on PreGCValues used in
>>> ParallelGC, as it’s a nice way to package up what’s needed in an object and
>>> easily re-use it in the few places where it’s needed. The way is done now,
>>> i.e., just store the metaspace used size and pass it to the print method,
>>> is a bit ad-hoc (IMHO).
>>>
>>>
>>>
>>> -> I would prefer the class PreMetaspaceValues to live inside an own
>>> header in metaspace folder, and in the metaspace namespace like we did for
>>> similar helpers.
>>>
>>>
>>> I can definitely do that.
>>>
>>>
>>>
>>> -> I would take the "Pre" out of the name and the member names and just
>>> name it "Snapshot" and the members "used" and "class used".
>>>
>>>
>>> Again, I modeled it based on ParallelGC's PreGCValues class. But I can
>>> rename it to Snapshot to generalize its use.
>>>
>>>
>>>
>>> -> I would probably have made PreMetaspaceValues a dumb structure and
>>> added a function "MetaspaceAux::get_dimensions()" instead of adding the
>>> implementation to the constructor and to the header file. At least I would
>>> prefer the ctor implementation to the cpp file.
>>>
>>>
>>> I can move it to a cpp file. This will also eliminate a cyclic
>>> dependency I had to address by the class forward declaration.
>>>
>>>
>>> Tony
>>>
>>>
>>>
>>>
>>> Cheers, Thomas
>>>
>>> On Wed, May 8, 2019 at 4:20 PM Tony Printezis <tprintezis at twitter.com>
>>> wrote:
>>>
>>>> Any chance of someone taking a look at this?
>>>>
>>>> http://cr.openjdk.java.net/~tonyp/8223575/webrev.0/
>>>>
>>>> As I said on the JIRA, users can be confused when they metaspace
>>>> capacity shows as over 1G even though they asked for 128M. Breaking down
>>>> the spaces, when coops are enabled, can address this confusion (and having
>>>> the actual occupancy of each space separately is also a lot more
>>>> informative and avoids guesswork). The output looks like this when coops
>>>> are enabled:
>>>>
>>>> [10.090s][info][gc,metaspace     ] GC(8) Metaspace:
>>>> 2130K->2130K(1056768K) ClassMetadata: 1906K->1906K(8192K) ClassSpace:
>>>> 223K->223K(1048576K)
>>>>
>>>> and like this (i.e., what it was before the change) when coops are not
>>>> enabled:
>>>>
>>>> [25.767s][info][gc,metaspace     ] GC(28) Metaspace:
>>>> 8107K->8107K(10240K)
>>>>
>>>> A couple of notes on the changes:
>>>>
>>>> - I’m open to different suggestions for what to call ClassMetadata and
>>>> ClassSpace. :-)
>>>> - I didn’t know where to put the HEAP_CHANGE_FORMAT and
>>>> HEAP_CHANGE_FORMAT_ARGS macros, so that they can be easily shared, and I
>>>> ended up putting them in heap.hpp. Let me know if there’s a better place
>>>> for them.
>>>>
>>>> Tony
>>>>
>>>>
>>>> —————
>>>> Tony Printezis | @TonyPrintezis | tprintezis at twitter.com
>>>>
>>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20190605/b8f6ee32/attachment.htm>