RFR(trivial): 8230037: Confused MetaData dumped by PrintOptoAssembly

[Vladimir Kozlov]

Hi Jie,

This looks good.

Thanks,
Vladimir

On 8/29/19 12:52 AM, Jie Fu wrote:
> Hi Vladimir and all,
> 
> Updated: http://cr.openjdk.java.net/~jiefu/8230037/webrev.01/
> 
> Apart from the example described in the JBS[1], here is a more confusing one.
> During debugging, people may think that the OptoAssembly @line 32383 should be for Compile_id=482 according to the 
> MetaData @line 32381.
> 
>    32355 ============================= C2-compiled nmethod ==============================
>    32356 ----------------------------------- MetaData -----------------------------------
>    32357 {method}
>    32358  - this oop:          0x00007f8b33c4a3f0
>    32359  - method holder: 'spec/benchmarks/compress/Compressor'
>    32360  - constants:         0x00007f8b33c497b0 constant pool [160] {0x00007f8b33c497b0} for 
> 'spec/benchmarks/compress/Compressor' cache=0x00007f8b33c4ab38
>    32361  - access:            0xc1000002  private
>    32362  - name:              'output'
>    32363  - signature:         '(I)V'
>    32364  - max stack:         7
>    32365  - max locals:        5
>    32366  - size of params:    2
>    32367  - method size:       13
>    32368  - highest level:     4
>    32369  - vtable index:      -2
>    32370  - i2i entry:         0x00007f8b70781460
>    32371  - adapters:          AHE at 0x00007f8b88426e90: 0xba000000 i2c: 0x00007f8b70b88800 c2i: 0x00007f8b70b8894d c2iUV: 
> 0x00007f8b70b88910 c2iNCI: 0x00007f8b70b8898a
>    32372  - compiled entry     0x00007f8b7838e0b0
>    32373  - code size:         373
>    32374  - code start:        0x00007f8b33c4a208
>    32375  - code end (excl):   0x00007f8b33c4a37d
>    32376  - method data:       0x00007f8b33c4d350
>    32377  - checked ex length: 0
>    32378  - linenumber start:  0x00007f8b33c4a37d
>    32379  - localvar length:   5
>    32380  - localvar start:    0x00007f8b33c4a3b2
>    32381  - compiled code: nmethod   1929  482       4 spec.benchmarks.compress.Compressor::output (373 bytes)
>    32382
>    32383 --------------------------------- OptoAssembly ---------------------------------
> 
> However, the MetaData[2] is always for the last compilation of the method, not for the current compilation.
> Therefore, it's wrong to match Compile_id for the OptoAssembly with the dumped MetaData.
> 
> So to find the correct Compile_id, the MetaData is *not only helpless but also quite misleading*.
> 
> The effect of the patch is the following.
> To avoid confusing, the Compile_id (@line 32356 and 32383) was dumped explicitly, which was inspired by Vladimir.
> Please see more comments inline.
> 
>    32355 ============================= C2-compiled nmethod ==============================
>    32356 ----------------------- MetaData before Compile_id = 485 ------------------------
>    32357 {method}
>    32358  - this oop:          0x00007f8b33c4a3f0
>    32359  - method holder: 'spec/benchmarks/compress/Compressor'
>    32360  - constants:         0x00007f8b33c497b0 constant pool [160] {0x00007f8b33c497b0} for 
> 'spec/benchmarks/compress/Compressor' cache=0x00007f8b33c4ab38
>    32361  - access:            0xc1000002  private
>    32362  - name:              'output'
>    32363  - signature:         '(I)V'
>    32364  - max stack:         7
>    32365  - max locals:        5
>    32366  - size of params:    2
>    32367  - method size:       13
>    32368  - highest level:     4
>    32369  - vtable index:      -2
>    32370  - i2i entry:         0x00007f8b70781460
>    32371  - adapters:          AHE at 0x00007f8b88426e90: 0xba000000 i2c: 0x00007f8b70b88800 c2i: 0x00007f8b70b8894d c2iUV: 
> 0x00007f8b70b88910 c2iNCI: 0x00007f8b70b8898a
>    32372  - compiled entry     0x00007f8b7838e0b0
>    32373  - code size:         373
>    32374  - code start:        0x00007f8b33c4a208
>    32375  - code end (excl):   0x00007f8b33c4a37d
>    32376  - method data:       0x00007f8b33c4d350
>    32377  - checked ex length: 0
>    32378  - linenumber start:  0x00007f8b33c4a37d
>    32379  - localvar length:   5
>    32380  - localvar start:    0x00007f8b33c4a3b2
>    32381  - compiled code: nmethod   1929  482       4 spec.benchmarks.compress.Compressor::output (373 bytes)
>    32382
>    32383 ------------------------ OptoAssembly for Compile_id = 485 -----------------------
> 
> Testing:
>    - make test TEST="tier1 tier2 tier3" CONF=fastdebug on Linux/x64
>    - make test TEST="tier1 tier2 tier3" CONF=release   on Linux/x64
>    - SPECjvm2008 with fastdebug using -XX:+PrintOptoAssembly on Linux/x64
> 
> Any comments?
> 
> Thanks a lot.
> Best regards,
> Jie
> 
> [1] https://bugs.openjdk.java.net/browse/JDK-8230037
> [2] http://hg.openjdk.java.net/jdk/jdk/file/3da1848cc39b/src/hotspot/share/opto/output.cpp#l1573
> 
> On 2019/8/23 上午12:16, Vladimir Kozlov wrote:
>> To avoid confusing I normally use -Xbatch and CICompilerCount=1 (or =2 for tiered compilation).
>>
>> The output is under ttyLocker so it should be one block. I see that there is mix of tty and xtty streams in code. May 
>> be that is the reason it is not together. 
> I had tested the tty and xtty logging with SPECjvm2008 on a 56-core machine.
> It works well enough for both of them (except for the safepoint case).
> 
> 
>> If we use xtty it should be passed to print_metadata() too. Please, investigate more.
> 
> I think there is no need to pass xtty to print_metadata() since
>   1) the ttyLocker also works for xtty [3]
>   2) and the tty and xtty actually will write to the same log file [4]
> 
> [3] http://hg.openjdk.java.net/jdk/jdk/file/3da1848cc39b/src/hotspot/share/opto/output.cpp#l1585
> [4] http://hg.openjdk.java.net/jdk/jdk/file/3da1848cc39b/src/hotspot/share/utilities/ostream.cpp#l645
> 
> 
>>
>> Instead of "Last Normal Compilation" I would print Compile_id.
> 
> Done. Thanks.
> 
> 
>>
>> Thanks,
>> Vladimir
>