8311976: Inconsistency in usage of CITimeVerbose to generate compilation logs

[ashu-mehra]

Please review this PR for controlling timing information of C1 compilation phases using CITimeVerbose option, same as for C2 compilations.
I also took this opportunity to fix some other minor issues with logging:

1. The PhaseTraceTime object should be constructed after setting the compiler data as PhaseTraceTime constructor calls Compilation::current(). For this reason I moved the statement PhaseTraceTime timeit(_t_compile) after the call to _env->set_compiler_data(this);.
2. Previous step also allowed to remove the nullptr check for Compilation::current() in PhaseTraceTime constructor.
3. I noticed the call to ComileLog->done() only prints phase_done tag and ignores all other parameters passed to it. This was due to a bug in xmlStream::va_done which is also fixed in here.
4. Remove unnecessary statements in TracePhase destructor as the object already has the fields computed in the constructor.
5. Some bikeshedding like TimerName -> TimerId and TracePhase::C -> TracePhase::_compile

I felt these are all minor fixes so I clubbed them together. here If it feel inappropriate I can pull them in their own PRs.

Testing: GHA testing passed

---

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-8311976: Inconsistency in usage of CITimeVerbose to generate compilation logs (Bug - P5)

Reviewers

• Vladimir Kozlov (@vnkozlov - Reviewer)
• Tobias Hartmann (@TobiHartmann - Reviewer)

Reviewing

Using git

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

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

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 14880

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

Using diff file

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

Webrev

Link to Webrev Comment

[bridgekeeper]

👋 Welcome back ashu-mehra! 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]

@ashu-mehra 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.

[mlbridge]

Webrevs

• 00: Full (c898e57e)

[vnkozlov]

@ashu-mehra, can you show output before and after this changes? It would be nice to see what you are fixing.

[ashu-mehra]

@vnkozlov

First change is in the amount of information in the C1 compilation log.

Before the fix with -XX:+LogCompilation (irrespective of CITimeVerbose), one example of each C1 and C2 compilation:

<task compile_id='1' method='java.lang.Object &lt;init&gt; ()V' bytes='1' count='389' iicount='389' level='3' stamp='0.051'>
<phase name='setup' stamp='0.051'>
<phase_done stamp='0.051'/>
</phase>
<phase name='buildIR' stamp='0.051'>
<type id='1213' name='void'/>
<klass id='1218' name='java.lang.Object' flags='1'/>
<method id='1387' holder='1218' name='&lt;init&gt;' return='1213' flags='1' bytes='1' iicount='390'/>
<parse method='1387'  stamp='0.051'>
<phase name='parse_hir' stamp='0.051'>
<bc code='177' bci='0'/>
<dependency type='no_finalizable_subclasses' ctxk='1218'/>
<phase_done stamp='0.051'/>
</phase>
<parse_done stamp='0.051'/>
</parse>
<phase name='optimize_blocks' stamp='0.051'>
<phase_done stamp='0.051'/>
</phase>
<phase name='gvn' stamp='0.051'>
<phase_done stamp='0.051'/>
</phase>
<phase name='rangeCheckElimination' stamp='0.051'>
<phase_done stamp='0.051'/>
</phase>
<phase name='optimize_null_checks' stamp='0.051'>
<phase_done stamp='0.051'/>
</phase>
<phase_done stamp='0.051'/>
</phase>
<phase name='emit_lir' stamp='0.051'>
<phase name='lirGeneration' stamp='0.051'>
<phase_done stamp='0.051'/>
</phase>
<phase name='linearScan' stamp='0.051'>
<phase_done stamp='0.052'/>
</phase>
<phase_done stamp='0.052'/>
</phase>
<phase name='codeemit' stamp='0.052'>
<phase_done stamp='0.052'/>
</phase>
<phase name='codeinstall' stamp='0.052'>
<dependency type='no_finalizable_subclasses' ctxk='1218'/>
<phase_done stamp='0.052'/>
</phase>
<code_cache total_blobs='651' nmethods='1' adapters='581' free_code_cache='249840128'/>
<task_done success='1' nmsize='304' count='399' stamp='0.052'/>
</task> 

<task compile_id='34' method='java.lang.Object &lt;init&gt; ()V' bytes='1' count='1424' iicount='1424' stamp='1.360'>
<type id='1213' name='void'/>
<klass id='1218' name='java.lang.Object' flags='1'/>
<method id='1387' holder='1218' name='&lt;init&gt;' return='1213' flags='1' bytes='1' compile_id='1' compiler='c1' level='3' iicount='1433'/>
<parse method='1387' uses='1433.000000' stamp='1.360'>
<bc code='177' bci='0'/>
<dependency type='no_finalizable_subclasses' ctxk='1218'/>
<parse_done stamp='1.360'/>
</parse>
<regalloc attempts='0' success='1'/>
<dependency type='no_finalizable_subclasses' ctxk='1218'/>
<code_cache total_blobs='777' nmethods='34' adapters='658' free_code_cache='249664128'/>
<task_done success='1' nmsize='136' count='1531' stamp='1.361'/>
</task>

Note that for C1 all phases are displayed, but not for C2. To include the phase information for C2, CITimeVerbose needs to be specified.

After the fix with -XX:+LogCompilation, example of C1 compilation:

<task compile_id='1' method='java.lang.Object &lt;init&gt; ()V' bytes='1' count='389' iicount='389' level='3' stamp='0.048'>
<type id='1213' name='void'/>
<klass id='1218' name='java.lang.Object' flags='1'/>
<method id='1387' holder='1218' name='&lt;init&gt;' return='1213' flags='1' bytes='1' iicount='389'/>
<parse method='1387'  stamp='0.048'>
<bc code='177' bci='0'/>
<dependency type='no_finalizable_subclasses' ctxk='1218'/>
<parse_done stamp='0.048'/>
</parse>
<dependency type='no_finalizable_subclasses' ctxk='1218'/>
<code_cache total_blobs='266' nmethods='1' adapters='192' free_code_cache='250510208'/>
<task_done success='1' nmsize='264' count='419' stamp='0.048'/>
</task>

and with -XX:+LogCompilation -XX:+CITimeVerbose example of C1 compilation:

<task compile_id='1' method='java.lang.Object &lt;init&gt; ()V' bytes='1' count='390' iicount='390' level='3' stamp='0.071'>
<phase name='compile' stamp='0.071'>
<phase name='setup' stamp='0.071'>
<phase_done name='setup' stamp='0.071'/>
</phase>
<phase name='buildIR' stamp='0.071'>
<type id='1213' name='void'/>
<klass id='1218' name='java.lang.Object' flags='1'/>
<method id='1387' holder='1218' name='&lt;init&gt;' return='1213' flags='1' bytes='1' iicount='390'/>
<parse method='1387'  stamp='0.071'>
<phase name='parse_hir' stamp='0.071'>
<bc code='177' bci='0'/>
<dependency type='no_finalizable_subclasses' ctxk='1218'/>
<phase_done name='parse_hir' stamp='0.071'/>
</phase>
<parse_done stamp='0.071'/>
</parse>
<phase name='optimize_blocks' stamp='0.071'>
<phase_done name='optimize_blocks' stamp='0.071'/>
</phase>
<phase name='gvn' stamp='0.071'>
<phase_done name='gvn' stamp='0.071'/>
</phase>
<phase name='rangeCheckElimination' stamp='0.071'>
<phase_done name='rangeCheckElimination' stamp='0.071'/>
</phase>
<phase name='optimize_null_checks' stamp='0.071'>
<phase_done name='optimize_null_checks' stamp='0.071'/>
</phase>
<phase_done name='buildIR' stamp='0.071'/>
</phase>
<phase name='emit_lir' stamp='0.071'>
<phase name='lirGeneration' stamp='0.071'>
<phase_done name='lirGeneration' stamp='0.071'/>
</phase>
<phase name='linearScan' stamp='0.071'>
<phase_done name='linearScan' stamp='0.071'/>
</phase>
<phase_done name='emit_lir' stamp='0.071'/>
</phase>
<phase name='codeemit' stamp='0.071'>
<phase_done name='codeemit' stamp='0.071'/>
</phase>
<phase name='codeinstall' stamp='0.071'>
<dependency type='no_finalizable_subclasses' ctxk='1218'/>
<phase_done name='codeinstall' stamp='0.071'/>
</phase>
<code_cache total_blobs='649' nmethods='1' adapters='581' free_code_cache='249835648'/>
<phase_done name='compile' stamp='0.071'/>
</phase>
<task_done success='1' nmsize='304' count='420' stamp='0.071'/>
</task>

Note that phase information for C1 compilation is now displayed only with CITimeVerbose option.
Output of C2 compilation in this context does not change with this patch.

The other change is in the phase_done tag to include the name of the phase just completed along with other data.

Before the fix:

<phase name='blockOrdering' nodes='13' live='13' stamp='3.191'>
<phase_done stamp='3.191'/>
</phase>

After the fix:

<phase name='blockOrdering' nodes='82' live='79' stamp='1.771'>
<phase_done name='blockOrdering' nodes='82' live='79' stamp='1.771'/>
</phase>

This makes it easier to trace the start and end of a phase even when there are sub-phases in between.

[vnkozlov]

Looks good. Thank you for showing output change.

[openjdk]

@ashu-mehra This change now passes all automated pre-integration checks.

ℹ️ This project also has non-automated pre-integration requirements. Please see the file CONTRIBUTING.md for details.

After integration, the commit message for the final commit will be:

8311976: Inconsistency in usage of CITimeVerbose to generate compilation logs

Reviewed-by: kvn, thartmann

You can use pull request commands such as /summary, /contributor and /issue to adjust it as needed.

At the time when this comment was updated there had been 85 new commits pushed to the master branch:

• 028068a: 8312166: (dc) DatagramChannel's socket adaptor does not release carrier thread when blocking in receive
• e7adbdb: 8311923: TestIRMatching.java fails on RISC-V
• c6ab9c2: 8308103: Massive (up to ~30x) increase in C2 compilation time since JDK 17
• d33e8e6: 8312200: Fix Parse::catch_call_exceptions memory leak
• f677793: 8312190: Fix c++11-narrowing warnings in hotspot code
• 82612e2: 8312329: Minimal build failure after JDK-8311541
• 702fea8: 8312147: Dynamic Exception Specification warnings are no longer required after JDK-8311380
• e5ecbff: 8312203: Improve specification of Array.newInstance
• c2f421b: 8311541: JavaThread::print_jni_stack doesn't support native stacks on all platforms
• e31df3a: 6211126: ICC_ColorSpace.toCIEXYZ(float[]): NPE is not specified
• ... and 75 more: https://git.openjdk.org/jdk/compare/119cc495fc6c18a29b7484d294c31ad1d478791c...master

As there are no conflicts, your changes will automatically be rebased on top of these commits when integrating. If you prefer to avoid this automatic rebasing, please check the documentation for the /integrate command for further details.

As you do not have Committer status in this project an existing Committer must agree to sponsor your change. Possible candidates are the reviewers of this PR (@vnkozlov, @TobiHartmann) but any other Committer may sponsor as well.

➡️ To flag this PR as ready for integration with the above commit message, type /integrate in a new comment. (Afterwards, your sponsor types /sponsor in a new comment to perform the integration).

[ashu-mehra]

@vnkozlov thanks for reviewing it.

[ashu-mehra]

Looking for one more reviewer for this patch.

[TobiHartmann]

Looks good to me.

[ashu-mehra]

/integrate

[openjdk]

@ashu-mehra
Your change (at version c898e57) is now ready to be sponsored by a Committer.

[tstuefe]

/sponsor

[openjdk]

Going to push as commit 3e8f1eb.
Since your change was applied there have been 109 commits pushed to the master branch:

• d4aacdb: 8306136: [vectorapi] Intrinsics of VectorMask.laneIsSet()
• 783de32: 8300051: assert(JvmtiEnvBase::environments_might_exist()) failed: to enter event controller, JVM TI environments must exist
• 4e8f331: 8312443: sun.security should use toLowerCase(Locale.ROOT)
• d7b9416: 8199149: Improve the exception message thrown by VarHandle of unsupported operation
• 354c660: 8307185: pkcs11 native libraries make JNI calls into java code while holding GC lock
• bae2247: 8308591: JLine as the default Console provider
• b772e67: 8312395: Improve assertions in growableArray
• 9fa944e: 8312019: Simplify and modernize java.util.BitSet.equals
• fe41910: 8312459: Problem list java/awt/GraphicsDevice/DisplayModes/CycleDMImage.java for macOS
• 8d29329: 8312320: Remove javax/rmi/ssl/SSLSocketParametersTest.sh from ProblemList
• ... and 99 more: https://git.openjdk.org/jdk/compare/119cc495fc6c18a29b7484d294c31ad1d478791c...master

Your commit was automatically rebased without conflicts.

[openjdk]

@tstuefe @ashu-mehra Pushed as commit 3e8f1eb.

💡 You may see a message that your pull request was closed with unmerged commits. This can be safely ignored.