8356027: Print enhanced compilation timings

[shipilev]

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.

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:

• Linux x86_64 server fastdebug, compiler
• Linux x86_64 server fastdebug, all

---

Progress

• Change must be properly reviewed (1 review required, with at least 1 Reviewer)
• Change must not contain extraneous whitespace
• Commit message must refer to an issue

Issue

• JDK-8356027: Print enhanced compilation timings (Enhancement - P4)

Reviewing

Using git

Checkout this PR locally:
$ git fetch https://git.openjdk.org/jdk.git pull/24984/head:pull/24984
$ git checkout pull/24984

Update a local copy of the PR:
$ git checkout pull/24984
$ git pull https://git.openjdk.org/jdk.git pull/24984/head

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 24984

View PR using the GUI difftool:
$ git pr show -t 24984

Using diff file

Download this PR as a diff file:
https://git.openjdk.org/jdk/pull/24984.diff

Using Webrev

Link to Webrev Comment

[bridgekeeper]

👋 Welcome back shade! A progress list of the required criteria for merging this PR into master will be added to the body of your pull request. There are additional pull request commands available for use with this pull request.

[openjdk]

❗ This change is not yet ready to be integrated.
See the Progress checklist in the description for automated requirements.

[openjdk]

@shipilev The following label will be automatically applied to this pull request:

• hotspot

When this pull request is ready to be reviewed, an "RFR" email will be sent to the corresponding mailing list. If you would like to change these labels, use the /label pull request command.

[shipilev]

Sample log after:

$ build/linux-x86_64-server-release/images/jdk/bin/java -XX:+PrintCompilation Hello.java
...
    344      0                   1351       3       java.util.Arrays::hashCode (15 bytes)   started
    345      0                   1350       3       java.util.Objects::hash (5 bytes)   started
    345      0                   1352       3       jdk.internal.util.ArraysSupport::hashCode (42 bytes)   started
    345      0      37      79   1349       3       java.lang.Byte::<init> (10 bytes)
    345      0                   1353       3       java.lang.Byte::hashCode (8 bytes)   started
    345      0      77      92   1351       3       java.util.Arrays::hashCode (15 bytes)
    345      0                   1354       3       java.lang.Byte::hashCode (2 bytes)   started
    345      0     212      66   1353       3       java.lang.Byte::hashCode (8 bytes)
    345      0     276      38   1354       3       java.lang.Byte::hashCode (2 bytes)
    345      0     139     167   1352       3       jdk.internal.util.ArraysSupport::hashCode (42 bytes)
    345      0      79     354   1348       3       java.lang.invoke.MemberName::hashCode (43 bytes)
    345      0     123     107   1350       3       java.util.Objects::hash (5 bytes)
...

This shows, for example, that C1 (tier3) compilations of these small methods are really quick, and the queueing delays are comparable to the actual compilation costs.

[shipilev]

Caught a failure in compiler/inlining/LateInlinePrinting.java -- we apparently rely in -XX:+PrintInlining to print the task before compilation, and then print inline tree after the compilation! With new started message there is a test error in matching. We also (reasonably) hold no ttyLock in between, so inline tree is not attributed well to the particular method if there are multiple compiler threads.

This is a blessing in disguise: with this change, we finally can start printing the inline tree after successful compiles under the ttyLock now. This also does -XX:+PrintInlining output only when -XX:+PrintCompilation is supplied (otherwise, where are you inlining into?), which I think is reasonable. Another test needs adjustments for this.

[mlbridge]

Webrevs

• 01: Full - Incremental (1a3b5a31)
• 00: Full (2c7e2154)