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

[Jie Fu]

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