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

[Calvin Cheung]

On Mon, 27 May 2024 04:19:08 GMT, David Holmes <dholmes at openjdk.org> wrote:

>> Calvin Cheung has updated the pull request incrementally with one additional commit since the last revision:
>> 
>>   @dholmes-ora comments
>
> 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

Fixed.

> 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?

I've changed them to JLONG_FORMAT and removed the casting.

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

This function will cover other sets of counters in the future. Maybe changing its name to `log_vm_stats`?

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

If using `tty`,  the output would lose the logging tag. The output would look as follows:

ClassLoader:
  clinit:               11ms / 285 events
  link methods:         13ms / 7493 events
  method adapters:      12ms / 571 events

versus with logging tag:

[0.094s][info][init] ClassLoader:
[0.094s][info][init]   clinit:               11ms / 278 events
[0.094s][info][init]   link methods:         13ms / 7336 events
[0.094s][info][init]   method adapters:      12ms / 571 events

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

I've changed it to the following:

    const char* name() const {
      assert(_timerp != nullptr, "sanity");
      return _timerp->name();
    }

> 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"?

Fixed.

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

PR Review Comment: https://git.openjdk.org/jdk/pull/18790#discussion_r1618181043
PR Review Comment: https://git.openjdk.org/jdk/pull/18790#discussion_r1618181124
PR Review Comment: https://git.openjdk.org/jdk/pull/18790#discussion_r1618181402
PR Review Comment: https://git.openjdk.org/jdk/pull/18790#discussion_r1618181476
PR Review Comment: https://git.openjdk.org/jdk/pull/18790#discussion_r1618181207
PR Review Comment: https://git.openjdk.org/jdk/pull/18790#discussion_r1618181263