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

Wed Jun 5 15:16:44 UTC 2019

Thomas,

Latest webrev based on (most!) of your suggestions:

http://cr.openjdk.java.net/~tonyp/8223575/webrev.3/

See inline.

—————
Tony Printezis | @TonyPrintezis | tprintezis at twitter.com

On June 5, 2019 at 1:58:17 AM, Thomas Stüfe (thomas.stuefe at gmail.com) wrote:

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.

Not sure why you think it’s different. I just get the values directly from
MetaspaceUtils the same way G1HeapTransition::Data gets the values from the
G1 heap:

G1HeapTransition::Data::Data(G1CollectedHeap* g1_heap) {
  _eden_length = g1_heap->eden_regions_count();
  _survivor_length = g1_heap->survivor_regions_count();
  _old_length = g1_heap->old_regions_count();
  _archive_length = g1_heap->archive_regions_count();
  _humongous_length = g1_heap->humongous_regions_count();
}

and also how PreGCValues (in ParallelGC) gets the values from the PS heap:

  PreGCValues(ParallelScavengeHeap* heap) :
      _heap_used(heap->used()),
      _young_gen_used(heap->young_gen()->used_in_bytes()),
      _old_gen_used(heap->old_gen()->used_in_bytes()) { }

The only difference is that in the metaspace case the methods are static
and in the other two cases the methods are on the heap object.

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

Sure, the *_used fields of PreGCValues are explicitly set (and similar for
G1HeapTransition::Data) whereas _meta_sizes is constructed implicitly. But
MetaspaceSizesSnapshot is also used outside PreGCValues and
G1HeapTransition::Data and it behaves the same as those two. So IMHO I
think it’s OK to leave it as is, as it is consistent with the other two.
The only difference is that MetaspaceSizesSnapshot is also embedded in the
other two (but also used stand-alone) and the other two are not embedded
anywhere else but only used stand-alone.

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.)

I renamed it as capacity (which I think is more generic) so we can set it
to anything else we want (in case someone is not happy with committed!)
while keeping code changes to a minimum. But, I changed it to committed (in
case we want to add reserved in the future).

--

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.

Good suggestion, done.

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 slightly rephrased the comment.

--

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).

I have no idea if a CSR is needed. Was there a CSR for the -Xlog:safepoint*
changes? I’ll assume one is not needed unless I’m told otherwise. ;-)

Tony

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/9adb3ab7/attachment.htm>