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

Wed May 15 08:11:06 UTC 2019

Hi Thomas,

Inline.

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

On May 13, 2019 at 2:51:48 PM, Thomas Stüfe (thomas.stuefe at gmail.com) wrote:

Hi Tony,

On Thu, May 9, 2019 at 6:38 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.
>
Not sure I follow. What the user could size is either MaxMetaspaceSize,
which would be the sum of committed for all sub spaces, or
CompressedClassSpaceSize, which would be the reserved size of the
compressed class space. In this output, both numbers are written out.

This was my bad. I had convinced myself that MaxMetaspaceSize only sets the
“non-class space” max size. But, my original arguments holds, though: It’s
nice to see the breakdown.

> 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
>
>
> Okay, lets assume it is fine to break existing scripts if we can make the
output better.

I agree.

>
> ---
>
> 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?
>
>
> Well, I'd say both are class metadata if you see it as runtime data
surrounding classes living outside the java heap. But I see what you mean.

This is a result of the decision to call the part of the Metaspace
containing the Klass structures "compressed class space", which is a slight
misnomer, since it is neither compressed nor really the (one exclusive)
Class Space.

:-)

 But then it follows that the other one is the "non-class space", or
alternatively the "metaspace" which is not much clearer since the whole is
also the Metaspace.

Yeah, but “non-class” is totally misleading here. Yes, yes, yes, I know I’m
being pedantic. But having to explain that to people has been a pain and
it’s confusing.

I agree that this is not perfect, but I would not like to introduce new
naming just now. That thing has been the "compressed class space" for a
long time. We have parameters like "CompressedClassSpaceSize" and tools
like "VM.metaspace" using that naming. We have numerous blogs and articles
referencing those names. And the terminology is clear if a bit strange. So
while I see your point, I would prefer to use the established naming scheme
we have now instead of creating a new one, and leave the naming discussion
for another day.

OK, I can go with Non-Class and Class, but in protest. :-)

Also: other metadata could move into the compressed class space in the
future, if we decide that they should be addressed with compressed
references. In theory, if some preconditions are met, we even could merge
both spaces and let just all metadata live in one contiguous range.

Also note that I currently work on a prototype for a JEP (
https://bugs.openjdk.java.net/browse/JDK-8221173) which revamps parts of
the Metaspace allocator. One outcome would be simplified and more generic
coding, with a lot less explicit decisions based on "class" or "non-class",
which may make the code base more amenable to you :)

We’ll see. :-)

>
> ---
>
> 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?
>
I had time to think about this a bit more and have some second thoughts. To
me, Reserved Size actually seems rather unimportant. If we scratch backward
compatibility and therefore can freely rework the message, lets think once
more:

We have four sizes standing out as candidates for reporting:
a) used size - which is what we use for class metadata.
b) committed size - which is what we actually spend on class metadata. This
is the size that hits MaxMetaspaceSize. This is also "what the OS sees what
we allocate" - the part of Metaspace contributing to RSS. It includes all
kind of wastages which on unhappy days can be significant, so (b) can be
larger than (a).
c) reserved size. For non-class space the reserved size follows very
closely the committed size, with a max delta of 4MB.  For the compressed
class space this size is just a constant which is usually not very
informative since it 1G is normally way too large to ever hit it.
d) the Maxima the user set - MaxMetaspaceSize and CompressedClassSpaceSize.
The former is just a number, but if we want to display something like "used
(maximum)" this would be a candidate. But it can be infinite. The latter is
equal to (c).

I find (b) the most interesting number, since it is what we pay for
Metaspace, including all overhead.

I agree that b) is a lot more interesting than c) and d) for the metaspace.
But a) and its difference from b) are the most interesting of all, IMHO.

Does the normal gc log for the heap not also print "committed”?

Yes, used / committed.

 So maybe we should swap "used" for "committed" in the output.

It might work for the metaspace but not for the GC. A lot of users, like
our devs at Twitter, run with a fixed heap size, which makes the used size
most interesting to report (the committed size is basically flat). The
difference between used and committed, as you say below, is also
interesting, but mostly for us, not the users (e.g., to keep an eye on
fragmentation I guess?). And it’d be nice to report the same metrics in
both cases otherwise it will create confusion (IMHO, at least). So, I’d
suggest used / committed for both metaspace and GC.

And then, the delta between used and committed is also interesting, since
this waste can get large. Finally, (c) is interesting only if you want to
know how much metaspace contributes to the virtual size of the process.

All IMHO, since I am no GC log expert.

What do you think? Maybe something like this:

"Metaspace: <committed> -> <committed> (class: <committed> -> <committed>,
non-class: <committed> -> <committed>)"

or

"Metaspace: <used>/<committed> -> <used>/<committed> (class:
<used>/<committed> -> <used>/<committed>, non-class: <used>/<committed> ->
<used>/<committed>)"

I’d go with this. You prefer used/committed to used(committed)? I’m OK
either way. But we should also change all GC output to the same form. It
will be unfortunate if they are different. Also, can I suggest we skip the
round brackets, as it will just unnecessary overhead when trying to parse
it. So:

Metaspace: used/committed->used/committed NonClass:
used/committed->used/committed Class: used/committed->used/committed

(NonClass is the non-class space, right? Should we have that first, as it’s
the more interesting space?)

or with reserved included as well:

"Metaspace: <used>/<committed>/<reserved>
->  <used>/<committed>/<reserved> (class:
<used>/<committed>/<reserved> ->  <used>/<committed>/<reserved>,
non-class:  <used>/<committed>/<reserved> ->  <used>/<committed>/<reserved>)"

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

>
> ---
>
> 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.
>
I think Oracle now testbuilds at least one no-pch build in jdk-submit.

OK, cool.

> 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.)?
>
>
> Alternatively you could move the printing code out of metaspace.cpp
completely and add it to some heap cpp file, since arguably it seems more
like metaspace printing on behalf of heap coding. I leave it up to you. If
you keep including heap.hpp, please include it explicitly. I think you may
pick it up by accident already which is why it did build for you.

>
> ----
>
> 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 agree. Using a structure here is way cleaner.

My original thoughts went like this: a number of callers seem all to wish
for a quick collection of metaspace statistics - those easy to obtain
without locking and walking structures - so lets give them a generic simple
API for it.

But as I wrote, this is all a matter of taste, and consolidating the
callers would be outside the scope of your change. Please go ahead and add
your proposed structure and API; if we wish, we can at some future point
consolidate the various callers to one API. Should not be too difficult.

> -> 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.
>
See above. If we plan for a later brush up of this API, do as you see fit.

>
>
> -> 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.
>
Thank you.

Just occurred to me, could you add a regression test? Or does one already
exist and need to be adapted?

Good point! I’ll look into that… (IIRC, I did run all the regressions tests
and got no failures; but I’ll double check…)

Tony

Cheers, Thomas

>
> 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/20190515/c8e74495/attachment.htm>