RFR: 8356027: Print enhanced compilation timings [v7]

[Aleksey Shipilev]

On Wed, 7 May 2025 08:03:29 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 with a new target base due to a merge or a rebase. The pull request now contains 13 commits:
> 
>  - Merge branch 'master' into JDK-8356027-print-compilation-timings
>  - Also handle UL printing
>  - Only record non-empty inlining messages
>  - Merge W+Q => Q
>  - Revert the shared printing block
>  - Add legend
>  - Merge branch 'master' into JDK-8356027-print-compilation-timings
>  - Test TestDuplicatedLateInliningOutput.java
>  - More touchups
>  - Fix TypeProfileFinalMethod as well
>  - ... and 3 more: https://git.openjdk.org/jdk/compare/50895835...2095d592

I started building the visualizer for the new output ([JDK-8356383](https://bugs.openjdk.org/browse/JDK-8356383)), and realized the millisecond timings for compiler events are a bit too coarse to be useful. With queue and compilation times in microseconds and below 1ms, the math to compute when the task was created accumulates visible errors. So I suggest we switch the first column to microseconds as well. This also makes output consistently in microseconds in all columns.

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

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