RFR: 8330198: Add some class loading related perf counters to measure VM startup [v4]

[David Holmes]

On Fri, 24 May 2024 23:25:15 GMT, Calvin Cheung <ccheung at openjdk.org> wrote:

>> Adding a few perf counters related to class loading to measure VM startup. The counters are only active if the user specifies `-Xlog:init` in the command line. A diagnostic flag `ProfileClassLinkage` is added to control the new counters. The flag is set to false by default and will be enabled if `-Xlog:init` is specified.
>> 
>> This change is already in the leyden/premain branch. There are more counters in the branch to measure other stuff. For now, just upstreaming class loader related counters.
>> 
>> Refer to the [comment](https://bugs.openjdk.org/browse/JDK-8330198?focusedId=14665311&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-14665311) in the bug report for an example output.
>> 
>> Passed tiers 1 - 4 testing.
>
> Calvin Cheung has updated the pull request incrementally with one additional commit since the last revision:
> 
>   @dholmes-ora comments

I have a few concerns about the way this is being put together. The coupling between the use of the perf counters and the unified logging seems awkward to me.

src/hotspot/share/cds/dynamicArchive.cpp line 123:

> 121: 
> 122:     log_info(cds,dynamic)("CDS dynamic dump: clinit = " INT64_FORMAT "ms)",
> 123:                           (int64_t)ClassLoader::class_init_time_ms());

Nit: just use JLONG_FORMAT and avoid the cast

src/hotspot/share/classfile/classLoader.cpp line 144:

> 142:       log.print_cr("ClassLoader:");
> 143:       log.print_cr("  clinit:               " INT64_FORMAT "ms / " INT64_FORMAT " events", (int64_t)ClassLoader::class_init_time_ms(), (int64_t)ClassLoader::class_init_count());
> 144:       log.print_cr("  link methods:         " INT64_FORMAT "ms / " INT64_FORMAT " events", (int64_t)Management::ticks_to_ms(_perf_ik_link_methods_time->get_value())   , (int64_t)_perf_ik_link_methods_count->get_value());

Why are you casting all the jlong values to int64_t instead of just using JLONG_FORMAT?

src/hotspot/share/runtime/java.cpp line 165:

> 163:     ClassLoader::print_counters();
> 164:   }
> 165: }

This method seems unnecessary. Inside `print_counters` it checks if the log is enabled and whether `ProfileClassLinkage` is set, so no need to check the log is enabled here. Wherever this is called you should just call `ClassLoader::print_counters` directly. (Further the "init" part of the name is only meaningful for the call site at the end of VM initialization.)

src/hotspot/share/runtime/java.cpp line 367:

> 365:   ThreadsSMRSupport::log_statistics();
> 366: 
> 367:   log_vm_init_stats();

Do we really want to call `ClassLoader::print_counters` here? IIUC most everything else here is printing to tty, but `ClassLoader::print_counters` will "print" to whereever the logging has been configured. (` ThreadsSMRSupport::log_statistics` seems similarly misplaced as it too uses logging).

src/hotspot/share/runtime/perfData.hpp line 838:

> 836:     }
> 837: 
> 838:     const char* name() const { return (_timerp != nullptr) ? _timerp->name() : nullptr; }

So now all the callers of this need a null check too. I wonder if this should just be an assertion check, as we should only ever call this when we have encountered a valid/live counter.

src/hotspot/share/runtime/threads.cpp line 832:

> 830: 
> 831:   if (ProfileClassLinkage) {
> 832:     log_info(init)("Before main:");

"Before main: " ?? That seems very launcher specific. How about "At VM initialization completion"?

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

Changes requested by dholmes (Reviewer).

PR Review: https://git.openjdk.org/jdk/pull/18790#pullrequestreview-2079957601
PR Review Comment: https://git.openjdk.org/jdk/pull/18790#discussion_r1615453134
PR Review Comment: https://git.openjdk.org/jdk/pull/18790#discussion_r1615453989
PR Review Comment: https://git.openjdk.org/jdk/pull/18790#discussion_r1615467369
PR Review Comment: https://git.openjdk.org/jdk/pull/18790#discussion_r1615480495
PR Review Comment: https://git.openjdk.org/jdk/pull/18790#discussion_r1615458516
PR Review Comment: https://git.openjdk.org/jdk/pull/18790#discussion_r1615460402