RFR: 8356027: Print enhanced compilation timings [v8]

[Aleksey Shipilev]

On Wed, 7 May 2025 11:51:04 GMT, Aleksey Shipilev <shade at openjdk.org> wrote:

>> In Leyden, we have the extended compilation timings printouts with -XX:+PrintCompilation / UL, that are very useful to study compiler dynamics. These timings include:
>>  1. Time spent before queuing: shows the compilation queue bottlenecks
>>  2. Time spent in the queue: shows delays caused by queue bottlenecks and compiler load
>>  3. Time spent actually compiling: shows the per-method compilation costs
>> 
>> We should consider the same kind of printout for mainline. This would also require us to print the compilation task _after_ the compilation, not only before it. This improvement would also obviate any need for `PrintCompilation2` flag, [JDK-8356028](https://bugs.openjdk.org/browse/JDK-8356028).
>> 
>> The difference from the output format we ship in Leyden:
>>  1. This output prints before/after the compilation to maintain old behavior partially. The "before" printout is now prepended with `started` to clearly mark it as such.
>>  2. The output is raw number in microseconds. In Leyden repo, we have these prepended with characters, like `C0.1`, but that prepending makes it a bit inconvenient with scripts. This PR also does microseconds, instead of fractional milliseconds. This should be enough to capture the wide range of durations.
>> 
>> See the sample `-XX:+PrintCompilation` output in the comments.
>> 
>> Additional testing:
>>  - [x] Linux x86_64 server fastdebug, `compiler`
>>  - [x]  Linux x86_64 server fastdebug, `all`
>
> Aleksey Shipilev has updated the pull request incrementally with one additional commit since the last revision:
> 
>   Do microseconds for timings

Well, this PR is essentially paying for our diagnostics debt.

We know this logging is useful for both humans, and with [JDK-8356383](https://bugs.openjdk.org/browse/JDK-8356383) also for tools. So we make the output useful for both. In fact, this is coming from Leyden, where the rich compilation logs were the nice diagnostic addition, which we (well, at least myself) used extensively to understand the compiler dynamics.

I agree UL is a more convenient vehicle for producing tool-readable files. This is why this PR handles UL as well. That said, `-XX:+PrintCompilation` is still a go-to tool for watching the compiler activity. Hiding good output behind yet another flag feels dubious to me. Adjusting `-XX:+PrintCompilation` output to capture most useful parts also simplifies our logging: we push the same strings to `tty` and `UL`, we do not need `Verbose` (debug only, btw, not accessible in the field) and `PrintCompilation2` flags, etc.

So, I remain a believer this is a right and useful thing to do.

I also note that -- as practical example -- AFAICS in Leyden this rich diagnostic logging was implemented for `PrintCompilation` while `LogCompilation` was kept intact. Which kinda tells which facility people actually use more :) I can put new stuff in `LogCompilation` output as well in this PR, BTW, if you want.

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

PR Comment: https://git.openjdk.org/jdk/pull/24984#issuecomment-2867091532