search

AdoptOpenJDK / jitwatch

Log analyser / visualiser for Java HotSpot JIT compiler. Inspect inlining decisions, hot methods, bytecode, and assembly. View results in the JavaFX user interface.
Other
3.06k stars 437 forks source link

New PrintOptoAssembly changes in OpenJDK 14 breaks HotSpot parser #309

Closed garyttierney closed 4 years ago

garyttierney commented 5 years ago

See: https://mail.openjdk.java.net/pipermail/hotspot-compiler-dev/2019-April/033395.html.

There are 2 sides to this problem.

1)

The [Disassembling for mach='%s'] directive is no longer present in the compilation log output. There's a comment in the HotSpot source code to this effect:

  // This event is problematic because it messes up the output.
  // The event is fired after the instruction address has already
  // been printed. The decoded instruction (event "insn") is
  // printed afterwards. That doesn't look nice.
  if (decode_env::match(event, "mach")) {
      ... snip ...

Since this isn't present the HotSpotParser is unable to split out AssemblyLines from the log file.

My fix for this is patching HotSpot to emit these events once again. I haven't seen a scenario where it messes up the output, but I'm using a custom hsdis plugin.

2)

New <opto_assembly> blocks containing disassembly (as well as some documentation tags) are present in the compilation log.

At the moment I've patched my local HotSpot to not emit these blocks, but it'd be neat to parse them and skip/deal with them correctly (I think you may even be able to gleam some additional information from some of the associated annotations).

I think there are two solutions available for 1) patch HotSpot to re-introduce these directives, or infer machine architecture from the host machine/environment.

For 2), it seems like the best first approach is to skip these blocks and continue and enhance it later. What do you think?

chriswhocodes commented 5 years ago

Thanks for the heads-up. I'll roll a JDK 14 build and see what the new output looks like and then try to fix up the parser to additionally support the new format.

Cheers,

Chris

garyttierney commented 5 years ago

Here's an example log file with some opto_assembly entries: https://jdkdev.z35.web.core.windows.net/hotspot-logs/mylogfile.log. The assembly here isn't produced by the hsdis plugin.

chriswhocodes commented 4 years ago

Looking into this now. Will adapt the parser to support all versions of the hsdis output.

chriswhocodes commented 4 years ago

OK it looks like this broke as early as JDK13.

Here is the disassembly log from a JDK12 run:

<nmethod compile_id='1' compiler='c1' level='3' entry='0x00007fbb40e3b1c0' size='912' address='0x00007fbb40e3b010' relocation_offset='376' insts_offset='432' stub_offset='656' scopes_data_offset='816' scopes_pcs
_offset='840' dependencies_offset='904' metadata_offset='800' method='java.lang.Object &lt;init&gt; ()V' bytes='1' count='256' iicount='256' stamp='0.016'/>
<print_nmethod stamp='0.016'>
Compiled method (c1)      16    1       3       java.lang.Object::&lt;init&gt; (1 bytes)
 total in heap  [0x00007fbb40e3b010,0x00007fbb40e3b3a0] = 912
 relocation     [0x00007fbb40e3b188,0x00007fbb40e3b1b0] = 40
 main code      [0x00007fbb40e3b1c0,0x00007fbb40e3b2a0] = 224
 stub code      [0x00007fbb40e3b2a0,0x00007fbb40e3b330] = 144
 metadata       [0x00007fbb40e3b330,0x00007fbb40e3b340] = 16
 scopes data    [0x00007fbb40e3b340,0x00007fbb40e3b358] = 24
 scopes pcs     [0x00007fbb40e3b358,0x00007fbb40e3b398] = 64
 dependencies   [0x00007fbb40e3b398,0x00007fbb40e3b3a0] = 8
Loaded disassembler from /home/chris/jdk12-chriswhocodes-nightly-linux-x86_64-release/lib/server/hsdis-amd64.so
----------------------------------------------------------------------
java/lang/Object.&lt;init&gt;()V  [0x00007fbb40e3b1c0, 0x00007fbb40e3b330]  368 bytes
[Disassembling for mach=&apos;i386:x86-64&apos;]
[Entry Point]
[Constants]
  # {method} {0x0000000800004098} &apos;&lt;init&gt;&apos; &apos;()V&apos; in &apos;java/lang/Object&apos;
  #           [sp+0x40]  (sp of caller)
  0x00007fbb40e3b1c0: mov    0x8(%rsi),%r10d
  0x00007fbb40e3b1c4: shl    $0x3,%r10
  0x00007fbb40e3b1c8: movabs $0x800000000,%r12
  0x00007fbb40e3b1d2: add    %r12,%r10
  0x00007fbb40e3b1d5: xor    %r12,%r12
  0x00007fbb40e3b1d8: cmp    %rax,%r10
  0x00007fbb40e3b1db: jne    0x00007fbb408d1680             ;   {runtime_call ic_miss_stub}
  0x00007fbb40e3b1e1: data16 data16 nopw 0x0(%rax,%rax,1)
  0x00007fbb40e3b1ec: data16 data16 xchg %ax,%ax
  0x00007fbb40e3b1f0: data16 data16 nopw 0x0(%rax,%rax,1)
  0x00007fbb40e3b1fb: data16 data16 xchg %ax,%ax
  0x00007fbb40e3b1ff: nop

compared with JDK13

<print_nmethod compile_id='1' compiler='c1' level='3' stamp='0.071'>

============================= C1-compiled nmethod ==============================
----------------------------------- Assembly -----------------------------------

Compiled method (c1)      72    1       3       java.lang.Object::&lt;init&gt; (1 bytes)
 total in heap  [0x00007fce68d35010,0x00007fce68d35380] = 880
 relocation     [0x00007fce68d35170,0x00007fce68d35198] = 40
 main code      [0x00007fce68d351a0,0x00007fce68d35280] = 224
 stub code      [0x00007fce68d35280,0x00007fce68d35310] = 144
 metadata       [0x00007fce68d35310,0x00007fce68d35320] = 16
 scopes data    [0x00007fce68d35320,0x00007fce68d35338] = 24
 scopes pcs     [0x00007fce68d35338,0x00007fce68d35378] = 64
 dependencies   [0x00007fce68d35378,0x00007fce68d35380] = 8

--------------------------------------------------------------------------------
[Constant Pool (empty)]

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

[Entry Point]
  # {method} {0x00000008003e1dc0} &apos;&lt;init&gt;&apos; &apos;()V&apos; in &apos;java/lang/Object&apos;
  #           [sp+0x40]  (sp of caller)
  0x00007fce68d351a0:   mov    0x8(%rsi),%r10d
  0x00007fce68d351a4:   shl    $0x3,%r10
  0x00007fce68d351a8:   movabs $0x800000000,%r12
  0x00007fce68d351b2:   add    %r12,%r10
  0x00007fce68d351b5:   xor    %r12,%r12
  0x00007fce68d351b8:   cmp    %rax,%r10
  0x00007fce68d351bb:   jne    0x00007fce687eed00           ;   {runtime_call ic_miss_stub}
  0x00007fce68d351c1:   data16 data16 nopw 0x0(%rax,%rax,1)
  0x00007fce68d351cc:   data16 data16 xchg %ax,%ax
  0x00007fce68d351d0:   data16 data16 nopw 0x0(%rax,%rax,1)
  0x00007fce68d351db:   data16 data16 xchg %ax,%ax
  0x00007fce68d351df:   nop
chriswhocodes commented 4 years ago

here is JDK14

<print_nmethod compile_id='1' compiler='c1' level='3' stamp='0.018'>

============================= C1-compiled nmethod ==============================
----------------------------------- Assembly -----------------------------------

Compiled method (c1)      18    1       3       java.lang.Object::&lt;init&gt; (1 bytes)
 total in heap  [0x00007f11f08d0010,0x00007f11f08d0320] = 784
 relocation     [0x00007f11f08d0168,0x00007f11f08d0190] = 40
 main code      [0x00007f11f08d01a0,0x00007f11f08d0280] = 224
 stub code      [0x00007f11f08d0280,0x00007f11f08d02b0] = 48
 metadata       [0x00007f11f08d02b0,0x00007f11f08d02c0] = 16
 scopes data    [0x00007f11f08d02c0,0x00007f11f08d02d8] = 24
 scopes pcs     [0x00007f11f08d02d8,0x00007f11f08d0318] = 64
 dependencies   [0x00007f11f08d0318,0x00007f11f08d0320] = 8

--------------------------------------------------------------------------------
[Constant Pool (empty)]

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

[Entry Point]
  # {method} {0x00000008003ebb38} &apos;&lt;init&gt;&apos; &apos;()V&apos; in &apos;java/lang/Object&apos;
  #           [sp+0x40]  (sp of caller)
  0x00007f11f08d01a0:   mov    0x8(%rsi),%r10d
  0x00007f11f08d01a4:   shl    $0x3,%r10
  0x00007f11f08d01a8:   movabs $0x800000000,%r12
  0x00007f11f08d01b2:   add    %r12,%r10
  0x00007f11f08d01b5:   xor    %r12,%r12
  0x00007f11f08d01b8:   cmp    %rax,%r10
  0x00007f11f08d01bb:   jne    0x00007f11f0388d00           ;   {runtime_call ic_miss_stub}
  0x00007f11f08d01c1:   data16 data16 nopw 0x0(%rax,%rax,1)
  0x00007f11f08d01cc:   data16 data16 xchg %ax,%ax
  0x00007f11f08d01d0:   data16 data16 nopw 0x0(%rax,%rax,1)
  0x00007f11f08d01db:   data16 data16 xchg %ax,%ax
  0x00007f11f08d01df:   nop

and here is JDK15

<print_nmethod compile_id='1' compiler='c1' level='3' stamp='0.052'>

============================= C1-compiled nmethod ==============================
----------------------------------- Assembly -----------------------------------

Compiled method (c1)      53    1       3       java.lang.Object::&lt;init&gt; (1 bytes)
 total in heap  [0x00007fec848c9010,0x00007fec848c9320] = 784
 relocation     [0x00007fec848c9168,0x00007fec848c9190] = 40
 main code      [0x00007fec848c91a0,0x00007fec848c9280] = 224
 stub code      [0x00007fec848c9280,0x00007fec848c92b0] = 48
 metadata       [0x00007fec848c92b0,0x00007fec848c92c0] = 16
 scopes data    [0x00007fec848c92c0,0x00007fec848c92d8] = 24
 scopes pcs     [0x00007fec848c92d8,0x00007fec848c9318] = 64
 dependencies   [0x00007fec848c9318,0x00007fec848c9320] = 8

--------------------------------------------------------------------------------
[Constant Pool (empty)]

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

[Entry Point]
  # {method} {0x00000008003ebd08} &apos;&lt;init&gt;&apos; &apos;()V&apos; in &apos;java/lang/Object&apos;
  #           [sp+0x40]  (sp of caller)
  0x00007fec848c91a0:   mov    0x8(%rsi),%r10d
  0x00007fec848c91a4:   shl    $0x3,%r10
  0x00007fec848c91a8:   movabs $0x800000000,%r12
  0x00007fec848c91b2:   add    %r12,%r10
  0x00007fec848c91b5:   xor    %r12,%r12
  0x00007fec848c91b8:   cmp    %rax,%r10
  0x00007fec848c91bb:   jne    0x00007fec84381d00           ;   {runtime_call ic_miss_stub}
  0x00007fec848c91c1:   data16 data16 nopw 0x0(%rax,%rax,1)
  0x00007fec848c91cc:   data16 data16 xchg %ax,%ax
  0x00007fec848c91d0:   data16 data16 nopw 0x0(%rax,%rax,1)
  0x00007fec848c91db:   data16 data16 xchg %ax,%ax
  0x00007fec848c91df:   nop
chriswhocodes commented 4 years ago

Fixed by modifying the assembly parser https://github.com/AdoptOpenJDK/jitwatch/commit/faf3c7de7330444347b1fbd544db5ccc551f3f5b

Thanks for reporting!