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

[Calvin Cheung]

On Tue, 4 Jun 2024 21:47:07 GMT, Calvin Cheung <ccheung at openjdk.org> wrote:

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

> > The -Xlog:init (perhaps with a better name/tag!)
> 

How about `-Xlog:initcounters` as the name/tag? It is similar to @dholmes-ora 's suggestion above without the underscore between "init" and "counters". Currently, none of the logging tag contains an underscore character.

@iwanowww, @iklam, @dholmes-ora, what do you guys think?

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

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