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

[Calvin Cheung]

On Tue, 4 Jun 2024 15:51:54 GMT, Ioi Lam <iklam at openjdk.org> wrote:

>>> -Xlog:init means "I want to see logs related to initialization", so it should enable all the counters for printing the related logs. 
>> 
>> I don't agree. Initialization logging could encompass many different things, some of which are individually controllable via different flags. Simply turning on init logging should not turn on all such flags. If you want that level of coupling then perhaps use init_counters (or something like that) to make it clear this is not a general log tag intended for any initialization code to use, but something you have chosen to tie to specific functionality.
>> 
>>> We may add several groups of counters in the future. We don't want to force the user to enumerate all these counters
>> 
>> It is not clear to me how you envisage that working. You want individual group switches plus a global one?
>
> OK, I agree that not `-Xlog:init` logs are related to timing. 
> 
> We actually have an existing tag that's used for conditional logging. Perhaps we should use that instead?
> 
> 
> ./share/logging/logTag.hpp:  LOG_TAG(startuptime) \
> ./share/memory/universe.cpp:  TraceTime timer("Genesis", TRACETIME_LOG(Info, startuptime));
> ./share/prims/methodHandles.cpp:  TraceTime timer("MethodHandles adapters generation", TRACETIME_LOG(Info, startuptime));
> ./share/runtime/stubRoutines.cpp:  TraceTime timer(timer_msg, TRACETIME_LOG(Info, startuptime));
> ./share/runtime/threads.cpp:  TraceTime timer("Initialize module system", TRACETIME_LOG(Info, startuptime));
> ./share/runtime/threads.cpp:  TraceTime timer("Initialize java.lang classes", TRACETIME_LOG(Info, startuptime));
> ./share/runtime/threads.cpp:  TraceTime timer("Initialize java.lang.invoke classes", TRACETIME_LOG(Info, startuptime));
> ./share/runtime/threads.cpp:  TraceTime timer("Create VM", TRACETIME_LOG(Info, startuptime));
> ./share/runtime/threads.cpp:  { TraceTime timer("Start VMThread", TRACETIME_LOG(Info, startuptime));
> ./share/runtime/timerTrace.hpp://    TraceTime t("some timer", TIMERTRACE_LOG(Info, startuptime, tagX...));
> ./share/utilities/ostream.cpp:  // lazily create log file (at startup, LogVMOutput is false even
> 
> $ java -Xlog:startuptime --version
> [0.010s][info][startuptime] StubRoutines generation initial stubs, 0.0006132 secs
> [0.025s][info][startuptime] Genesis, 0.0145142 secs
> [0.025s][info][startuptime] StubRoutines generation continuation stubs, 0.0000198 secs
> [0.028s][info][startuptime] Interpreter generation, 0.0005919 secs
> [0.028s][info][startuptime] StubRoutines generation final stubs, 0.0000717 secs
> [0.028s][info][startuptime] MethodHandles adapters generation, 0.0000101 secs
> [0.029s][info][startuptime] Start VMThread, 0.0000846 secs
> [0.032s][info][startuptime] Initialize java.lang classes, 0.0036507 secs
> [0.033s][info][startuptime] Initialize java.lang.invoke classes, 0.0002106 secs
> [0.034s][info][startuptime] StubRoutines generation compiler stubs, 0.0015061 secs
> [0.035s][info][startuptime] Initialize module system, 0.0017471 secs
> [0.035s][info][startuptime] Create VM, 0.0305224 secs
> java 23-internal 2024-09-17
> Java(TM) SE Runtime Environment (build 23-internal-adhoc.iklam.zoo)
> Java HotSpot(TM) 64-Bit Server VM (build 23-internal-adhoc.iklam.zoo, mixed mode, sharing)

The `TraceTime` doesn't fit what we need well. All the function using `TraceTime `will be called only once.
I tried it in `LinkResolver::resolve_invokehandle`

void LinkResolver::resolve_invokehandle(CallInfo& result, const constantPoolHandle& pool, int index, TRAPS) {

  TraceTime trace_timer("Resolve invokehandle", TRACETIME_LOG(Info, startuptime));

When I run a HelloWorld with `-Xlog:startuptime`, I saw:

[0.008s][info][startuptime] StubRoutines generation initial stubs, 0.0005199 secs
[0.060s][info][startuptime] Genesis, 0.0519067 secs
[0.060s][info][startuptime] StubRoutines generation continuation stubs, 0.0000791 secs
[0.069s][info][startuptime] Interpreter generation, 0.0022987 secs
[0.082s][info][startuptime] StubRoutines generation final stubs, 0.0012770 secs
[0.082s][info][startuptime] MethodHandles adapters generation, 0.0001008 secs
[0.082s][info][startuptime] Start VMThread, 0.0001566 secs
[0.092s][info][startuptime] Initialize java.lang classes, 0.0101517 secs
[0.094s][info][startuptime] Initialize java.lang.invoke classes, 0.0007457 secs
[0.097s][info][startuptime] StubRoutines generation compiler stubs, 0.0035488 secs
[0.100s][info][startuptime] Initialize module system, 0.0064275 secs
[0.101s][info][startuptime] Create VM, 0.1007149 secs
[0.135s][info][startuptime] Resolve invokehandle, 0.0004090 secs
[0.135s][info][startuptime] Resolve invokehandle, 0.0000021 secs
[0.135s][info][startuptime] Resolve invokehandle, 0.0000009 secs
[0.137s][info][startuptime] Resolve invokehandle, 0.0002939 secs
[0.137s][info][startuptime] Resolve invokehandle, 0.0000017 secs
[0.139s][info][startuptime] Resolve invokehandle, 0.0001010 secs
[0.139s][info][startuptime] Resolve invokehandle, 0.0000016 secs
[0.143s][info][startuptime] Resolve invokehandle, 0.0000026 secs
hello, world

Also, I think `TraceTime` doesn't have a counter to track the number of times the function is called.

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

PR Review Comment: https://git.openjdk.org/jdk/pull/18790#discussion_r1626637404