RFR: 8217327: G1 Post-Cleanup region liveness printing should not print out-of-date efficiency [v3]

[Thomas Schatzl]

On Thu, 28 Jan 2021 08:44:54 GMT, Joakim Nordström <github.com+779991+jaokim at openjdk.org> wrote:

>> **Description**
>> This fix addresses the issue where gc-efficiency is printed incorrectly when logging post-marking and post-cleanup. The gc-efficiency is calculated in the end of the marking phase, to be logged in the post-cleanup section. It is however not reset, meaning that next phase's post-marking log will show the old value.
>> 
>> - The gc-efficiency is initialized to -1 when it hasn't been calculated.
>> - Negative gc-efficiency is displayed as a hyphen "-" in the summary.
>> - The gc-efficiency is reset to -1 in `HeapRegion::note_start_of_marking()`
>> 
>> **Note:** there is a sister issue that moves the post-cleanup printing to a later stage. Without this fix, the logging will still be incorrect, so both fixes are needed. See: [JDK-8260042: G1 Post-cleanup liveness printing occurs too early](https://github.com/openjdk/jdk/pull/2168)
>> 
>> This fix has been tested together with the above mentioned fix.
>> 
>> **Example**
>> This is what logging like after fix has been applied.
>> ### PHASE Post-Marking @ 410.303
>> ### HEAP  reserved: 0x0ffc00000-0x100000000  region-size: 1048576
>> ###
>> ###   type           address-range       used  prev-live  next-live          gc-eff     remset   state  code-roots
>> ###                                                 (bytes)    (bytes)    (bytes)      (bytes/ms)    (bytes)            (bytes)
>> ###   OLD  0x0ffc00000-0x0ffd00000    1048368    1048368    1048368               -       8464   UPDAT       6096
>> ###   OLD  0x0ffd00000-0x0ffe00000     132856     132856     132856               -       2544   UPDAT         16
>> ###   SURV 0x0ffe00000-0x0fff00000      21368      21368      21368               -       2544   CMPLT         16
>> ###   FREE 0x0fff00000-0x100000000          0          0          0               -       2384   UNTRA         16
>> ###
>> ### SUMMARY  capacity: 4.00 MB  used: 1.15 MB / 28.67 %  prev-live: 1.15 MB / 28.67 %  next-live: 1.15 MB / 28.67 %  remset: 0.02 MB  code-roots: 0.01 MB
>> ### PHASE Post-Cleanup @ 410.305
>> ### HEAP  reserved: 0x0ffc00000-0x100000000  region-size: 1048576
>> ###
>> ###   type           address-range       used  prev-live  next-live          gc-eff     remset   state  code-roots
>> ###                                                 (bytes)    (bytes)    (bytes)      (bytes/ms)    (bytes)            (bytes)
>> ###   OLD  0x0ffc00000-0x0ffd00000    1048368    1048368    1048368               -       8624   UNTRA       6096
>> ###   OLD  0x0ffd00000-0x0ffe00000     132856     132856     132856       1352923.9       2544   CMPLT         16
>> ###   SURV 0x0ffe00000-0x0fff00000      21368      21368      21368               -       2544   CMPLT         16
>> ###   FREE 0x0fff00000-0x100000000          0          0          0               -       2384   UNTRA         16
>> ###
>> ### SUMMARY  capacity: 4.00 MB  used: 1.15 MB / 28.67 %  prev-live: 1.15 MB / 28.67 %  next-live: 1.15 MB / 28.67 %  remset: 0.02 MB  code-roots: 0.01 MB
>> ### PHASE Post-Marking @ 450.310
>> ### HEAP  reserved: 0x0ffc00000-0x100000000  region-size: 1048576
>> ###
>> ###   type           address-range       used  prev-live  next-live          gc-eff     remset   state  code-roots
>> ###                                                 (bytes)    (bytes)    (bytes)      (bytes/ms)    (bytes)            (bytes)
>> ###   OLD  0x0ffc00000-0x0ffd00000    1048368    1048368    1048368               -       8624   UPDAT       6096
>> ###   OLD  0x0ffd00000-0x0ffe00000     174456     174456     174456               -       2544   UPDAT         16
>> ###   SURV 0x0ffe00000-0x0fff00000      21368      21368      21368               -       2544   CMPLT         16
>> ###   FREE 0x0fff00000-0x100000000          0          0          0               -       2384   UNTRA         16
>> ###
>> ### SUMMARY  capacity: 4.00 MB  used: 1.19 MB / 29.66 %  prev-live: 1.19 MB / 29.66 %  next-live: 1.19 MB / 29.66 %  remset: 0.02 MB  code-roots: 0.01 MB
>> ### PHASE Post-Cleanup @ 450.312
>> ### HEAP  reserved: 0x0ffc00000-0x100000000  region-size: 1048576
>> ###
>> ###   type           address-range       used  prev-live  next-live          gc-eff     remset   state  code-roots
>> ###                                                 (bytes)    (bytes)    (bytes)      (bytes/ms)    (bytes)            (bytes)
>> ###   OLD  0x0ffc00000-0x0ffd00000    1048368    1048368    1048368               -       8624   UNTRA       6096
>> ###   OLD  0x0ffd00000-0x0ffe00000     174456     174456     174456       1266519.2       2544   CMPLT         16
>> ###   SURV 0x0ffe00000-0x0fff00000      21368      21368      21368               -       2544   CMPLT         16
>> ###   FREE 0x0fff00000-0x100000000          0          0          0               -       2384   UNTRA         16
>> ###
>> 
>> **Testing**
>> - Manual testing
>> - hs-tier1, hs-tier2
>
> Joakim Nordström has updated the pull request incrementally with one additional commit since the last revision:
> 
>   Added format buffer and fixed duplicated code

Note that I think the code given is correct, so I am good if you think using `snprintf` is better but I want your feedback about this. Then I'll approve.

src/hotspot/share/gc/g1/g1ConcurrentMark.cpp line 2983:

> 2981: 
> 2982:   if(gc_eff < 0) {
> 2983:     snprintf(gc_efficiency, G1PPRL_DOUBLE_FORMAT_LEN+1, G1PPRL_DOUBLE_H_FORMAT, "-");

snprintf is fine with me too, but I had imagined something like this:

FormatBuffer<> efficiency(""); //  maybe better name this
if (gc_eff < 0.0) {
  efficiency.append("-");
} else {
  efficiency.append(G1PPRL_DOUBLE_H_FORMAT, gc_eff);
}

and in the `log_trace` use `%s` and `efficiency.buffer()`. That seems a lot easier to understand (for me) than wrangling with `snprintf`.

Maybe there is a reason to not use this?

Also, I am not sure that using `G1PPRL_DOUBLE_H_FORMAT` for this `snprintf` here to print only `-` is really correct. I would have naively have expected to require `%s`.

-------------

Changes requested by tschatzl (Reviewer).

PR: https://git.openjdk.java.net/jdk/pull/2217