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

[Ioi Lam]

On Wed, 5 Jun 2024 04:02:18 GMT, Calvin Cheung <ccheung at openjdk.org> wrote:

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

While these counters are useful for start-up measurement, they can be used for other purposes (e.g., monitoring how much time is spend in linking classes in a long running application). So I think the logging tag should be more neutral.

We already have `-Xlog:perf`. Maybe we can have sub options like `-Xlog:perf+class+link` for the counters in this PR?

I know an upcoming PR will be for stats for MutexLocker. Something like `-Xlog:perf+lock` would work for such stats.

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

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