RFR: 8359110: Log accumulated GC and process CPU time upon VM exit [v3]

[Thomas Schatzl]

On Thu, 12 Jun 2025 15:25:08 GMT, Jonas Norlinder <duke at openjdk.org> wrote:

>> Add support to log CPU cost for GC during VM exit with `-Xlog:gc`.
>> 
>> 
>> [1.500s][info ][gc] GC CPU cost: 1.75%
>> 
>> 
>> Additionally, detailed information may be retrieved with `-Xlog:gc=trace`
>> 
>> 
>> [1.500s][trace][gc] Process CPU time: 4.945370s
>> [1.500s][trace][gc] GC CPU time: 0.086382s
>> [1.500s][info ][gc] GC CPU cost: 1.75%
>
> Jonas Norlinder has updated the pull request incrementally with two additional commits since the last revision:
> 
>  - Refactor shared logic into CollectedHeap, remove nominal logging and cost->usage
>  - Remove unnecessary assert

The string deduplication thread, which is to some degree also a GC helper thread, is not considered here. Not sure if it should, slightly tending to add it.

src/hotspot/share/gc/parallel/parallelScavengeHeap.cpp line 164:

> 162: 
> 163: void ParallelScavengeHeap::stop() {
> 164:   log_gc_vtime();

I think in OO-fashion, instead of adding the `log_gc_vtime()` call everywhere, it should be called in the super-class method and the others defer to it.

src/hotspot/share/gc/serial/serialHeap.cpp line 153:

> 151: 
> 152: double SerialHeap::elapsed_gc_vtime() {
> 153:   return (double) Universe::heap()->vm_vtime() / NANOSECS_PER_SEC;

This specialization does not seem necessary. Serial GC also has `gc_threads_do()`, which does nothing, as expected.

src/hotspot/share/gc/shared/collectedHeap.cpp line 239:

> 237:     double gc_vtime = elapsed_gc_vtime();
> 238: 
> 239:     if (process_vtime == -1 || gc_vtime == -1) return;

I would prefer to add braces to avoid overlooking this return statement in this context.

src/hotspot/share/gc/z/zCollectedHeap.cpp line 123:

> 121:       Atomic::add(&_vtime, os::thread_cpu_time(thread));
> 122:     }
> 123:   }

Why does this exclude threads like the `ZDirector` and other ZGC background threads? That thread seems to clearly be relevant to ZGC operation, doing so would make the measurement incomplete.
The change does not exclude e.g. some random G1 "director" threads either, even if they do not contribute much to the result.

src/hotspot/share/gc/z/zCollectedHeap.cpp line 130:

> 128:   ZVCPUThreadClosure cl;
> 129:   gc_threads_do(&cl);
> 130:   return (double)(cl.vtime() + Universe::heap()->vm_vtime()) / NANOSECS_PER_SEC;

Taking the comment about missing ZGC threads into account, it seems `elapsed_gc_vtime()` can be implemented without any need of overrides in `CollectedHeap`.

src/hotspot/share/runtime/vmOperation.hpp line 171:

> 169:   virtual bool evaluate_at_safepoint() const { return true; }
> 170: 
> 171:   virtual bool operation_is_gc() const { return false; }

This method seems to be never read anywhere. Is this correct?

src/hotspot/share/runtime/vmThread.cpp line 282:

> 280: 
> 281:     EventExecuteVMOperation event;
> 282:     VTimeScope vTimeScope(this);

Not sure if it is the intent of this change to put all VM operations into the "GC" bucket, particularly because of the log message indicating so. I would prefer if really only GC operations would be counted here; `VTimeScope` does not use `operation_is_gc()` either, so I am not sure about the intention here.

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

Changes requested by tschatzl (Reviewer).

PR Review: https://git.openjdk.org/jdk/pull/25779#pullrequestreview-2921860873
PR Review Comment: https://git.openjdk.org/jdk/pull/25779#discussion_r2144665083
PR Review Comment: https://git.openjdk.org/jdk/pull/25779#discussion_r2144669651
PR Review Comment: https://git.openjdk.org/jdk/pull/25779#discussion_r2143164063
PR Review Comment: https://git.openjdk.org/jdk/pull/25779#discussion_r2144687225
PR Review Comment: https://git.openjdk.org/jdk/pull/25779#discussion_r2144693093
PR Review Comment: https://git.openjdk.org/jdk/pull/25779#discussion_r2144695741
PR Review Comment: https://git.openjdk.org/jdk/pull/25779#discussion_r2143169291