RFR: 8311976: Inconsistency in usage of CITimeVerbose to generate compilation logs

Thu Jul 13 23:56:14 UTC 2023

On Thu, 13 Jul 2023 23:07:35 GMT, Vladimir Kozlov <kvn at openjdk.org> wrote:

>> 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
>
> @ashu-mehra, can you show output before and after this changes? It would be nice to see what you are fixing.

@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 <init> ()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='<init>' 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 <init> ()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='<init>' 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 <init> ()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='<init>' 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 <init> ()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='<init>' 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.

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

PR Comment: https://git.openjdk.org/jdk/pull/14880#issuecomment-1635066400