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

Missing assembly view #292

Closed animeshtrivedi closed 2 years ago

animeshtrivedi commented 5 years ago

Hi @chriswhocodes - (thanks for developing this wonderful tool).

Setup : Ubuntu 16.04 with Oracle JDK 1.8.151

I am running the code on a server machine and using my local client machine to analyze the JIT log. Both the server and the client machine have identical OSes and JVM versions. The sever has hsdis, and the assembly is generated in the log. However, it is not shown (on the client machine) in the TriView plane.

When I click on the compiled method, I see this pop up on the console 

17:19:35.598 [JavaFX Application Thread] WARN  o.a.j.c.CompilationUtil - No Task found in Compilation 1451
17:19:35.599 [JavaFX Application Thread] WARN  o.a.j.c.CompilationUtil - No Task found in Compilation 1451

image

chriswhocodes commented 5 years ago

Hi Animesh, How big is the hotspot log file? Any chance you could zip it up and email it to me or if it's small enough post it as a gist? My email is chris@chrisnewland.com Thanks!

animeshtrivedi commented 5 years ago

Hi Chris - sent you the log file. Thanks for your help.

animeshtrivedi commented 5 years ago

FYI: The corresponding code is here https://github.com/animeshtrivedi/benchmarking-arrow/tree/trail

chriswhocodes commented 5 years ago

Hi Animesh, I've built your code and tried to load your logfile but there is a mismatch in the bytecode (see red highlights) so I don't think the current head of your repo matches the code that ran when the logfile was generated?

I've added some more debug around the "Missing Task" situation so if you could update your jitwatch copy and try again please? Let me know what is printed in the console after the line: No Task found in Compilation ... Thanks

trivedi

animeshtrivedi commented 5 years ago

Hi Chris - yes, I updated that ("trail") branch with more code. Sorry about that. I think the log corresponds to the commit (e9aca7ea01c0ff7151bd2696e3c4269982c447f7) on that branch.

Let me try the updated JITWatch and get back to you.

animeshtrivedi commented 5 years ago

Hi Chris, so on the master branch of the code, I get this. There are some missing classes in the code for which I get these exceptions. I hope this is not an issue. Furthermore, in another codepath I do get the assembly view working. Somehow this particular routine (consumeInt4) has some issues.

The two lines (No Task found in Compilation 1431) that are printed at the end of the log are from CompilationUtil.java line 67 and 145. 

11:09:11.073 [Thread-3] ERROR o.a.j.p.AbstractLogParser - Could not addClassToModel com.google.common.collect.ImmutableCollection$EmptyImmutableCollection
java.lang.VerifyError: class com.google.common.collect.ImmutableCollection$EmptyImmutableCollection overrides final method toArray.([Ljava/lang/Object;)[Ljava/lang/Object;
    at java.lang.ClassLoader.defineClass1(Native Method) ~[na:1.8.0_151]
    at java.lang.ClassLoader.defineClass(ClassLoader.java:763) ~[na:1.8.0_151]
    at java.security.SecureClassLoader.defineClass(SecureClassLoader.java:142) ~[na:1.8.0_151]
    at java.net.URLClassLoader.defineClass(URLClassLoader.java:467) ~[na:1.8.0_151]
    at java.net.URLClassLoader.access$100(URLClassLoader.java:73) ~[na:1.8.0_151]
    at java.net.URLClassLoader$1.run(URLClassLoader.java:368) ~[na:1.8.0_151]
    at java.net.URLClassLoader$1.run(URLClassLoader.java:362) ~[na:1.8.0_151]
    at java.security.AccessController.doPrivileged(Native Method) ~[na:1.8.0_151]
    at java.net.URLClassLoader.findClass(URLClassLoader.java:361) ~[na:1.8.0_151]
    at java.lang.ClassLoader.loadClass(ClassLoader.java:424) ~[na:1.8.0_151]
    at java.lang.ClassLoader.loadClass(ClassLoader.java:357) ~[na:1.8.0_151]
    at java.lang.Class.forName0(Native Method) ~[na:1.8.0_151]
    at java.lang.Class.forName(Class.java:348) ~[na:1.8.0_151]
    at org.adoptopenjdk.jitwatch.util.ClassUtil.loadClassWithoutInitialising(ClassUtil.java:50) ~[classes/:na]
    at org.adoptopenjdk.jitwatch.parser.AbstractLogParser.addToClassModel(AbstractLogParser.java:302) [classes/:na]
    at org.adoptopenjdk.jitwatch.parser.hotspot.HotSpotLogParser.buildClassModel(HotSpotLogParser.java:500) [classes/:na]
    at org.adoptopenjdk.jitwatch.parser.hotspot.HotSpotLogParser.buildClassModel(HotSpotLogParser.java:460) [classes/:na]
    at org.adoptopenjdk.jitwatch.parser.hotspot.HotSpotLogParser.parseLogFile(HotSpotLogParser.java:128) [classes/:na]
    at org.adoptopenjdk.jitwatch.parser.AbstractLogParser.processLogFile(AbstractLogParser.java:365) [classes/:na]
    at org.adoptopenjdk.jitwatch.ui.main.JITWatchUI$1.run(JITWatchUI.java:239) [classes/:na]
    at java.lang.Thread.run(Thread.java:748) [na:1.8.0_151]
11:09:11.079 [Thread-3] ERROR o.a.j.p.AbstractLogParser - Could not addClassToModel com.google.common.collect.EmptyImmutableList
java.lang.VerifyError: class com.google.common.collect.EmptyImmutableList overrides final method toArray.([Ljava/lang/Object;)[Ljava/lang/Object;
    at java.lang.ClassLoader.defineClass1(Native Method) ~[na:1.8.0_151]
    at java.lang.ClassLoader.defineClass(ClassLoader.java:763) ~[na:1.8.0_151]
    at java.security.SecureClassLoader.defineClass(SecureClassLoader.java:142) ~[na:1.8.0_151]
    at java.net.URLClassLoader.defineClass(URLClassLoader.java:467) ~[na:1.8.0_151]
    at java.net.URLClassLoader.access$100(URLClassLoader.java:73) ~[na:1.8.0_151]
    at java.net.URLClassLoader$1.run(URLClassLoader.java:368) ~[na:1.8.0_151]
    at java.net.URLClassLoader$1.run(URLClassLoader.java:362) ~[na:1.8.0_151]
    at java.security.AccessController.doPrivileged(Native Method) ~[na:1.8.0_151]
    at java.net.URLClassLoader.findClass(URLClassLoader.java:361) ~[na:1.8.0_151]
    at java.lang.ClassLoader.loadClass(ClassLoader.java:424) ~[na:1.8.0_151]
    at java.lang.ClassLoader.loadClass(ClassLoader.java:357) ~[na:1.8.0_151]
    at java.lang.Class.forName0(Native Method) ~[na:1.8.0_151]
    at java.lang.Class.forName(Class.java:348) ~[na:1.8.0_151]
    at org.adoptopenjdk.jitwatch.util.ClassUtil.loadClassWithoutInitialising(ClassUtil.java:50) ~[classes/:na]
    at org.adoptopenjdk.jitwatch.parser.AbstractLogParser.addToClassModel(AbstractLogParser.java:302) [classes/:na]
    at org.adoptopenjdk.jitwatch.parser.hotspot.HotSpotLogParser.buildClassModel(HotSpotLogParser.java:500) [classes/:na]
    at org.adoptopenjdk.jitwatch.parser.hotspot.HotSpotLogParser.buildClassModel(HotSpotLogParser.java:460) [classes/:na]
    at org.adoptopenjdk.jitwatch.parser.hotspot.HotSpotLogParser.parseLogFile(HotSpotLogParser.java:128) [classes/:na]
    at org.adoptopenjdk.jitwatch.parser.AbstractLogParser.processLogFile(AbstractLogParser.java:365) [classes/:na]
    at org.adoptopenjdk.jitwatch.ui.main.JITWatchUI$1.run(JITWatchUI.java:239) [classes/:na]
    at java.lang.Thread.run(Thread.java:748) [na:1.8.0_151]
Exception in thread "Thread-3" java.lang.VerifyError: class com.google.common.collect.EmptyImmutableList overrides final method toArray.([Ljava/lang/Object;)[Ljava/lang/Object;
    at java.lang.ClassLoader.defineClass1(Native Method)
    at java.lang.ClassLoader.defineClass(ClassLoader.java:763)
    at java.security.SecureClassLoader.defineClass(SecureClassLoader.java:142)
    at java.net.URLClassLoader.defineClass(URLClassLoader.java:467)
    at java.net.URLClassLoader.access$100(URLClassLoader.java:73)
    at java.net.URLClassLoader$1.run(URLClassLoader.java:368)
    at java.net.URLClassLoader$1.run(URLClassLoader.java:362)
    at java.security.AccessController.doPrivileged(Native Method)
    at java.net.URLClassLoader.findClass(URLClassLoader.java:361)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
    at java.lang.Class.forName0(Native Method)
    at java.lang.Class.forName(Class.java:348)
    at org.adoptopenjdk.jitwatch.util.ClassUtil.loadClassWithoutInitialising(ClassUtil.java:50)
    at org.adoptopenjdk.jitwatch.util.ParseUtil.lateLoadMetaClass(ParseUtil.java:1098)
    at org.adoptopenjdk.jitwatch.model.JITDataModel.findMetaMember(JITDataModel.java:304)
    at org.adoptopenjdk.jitwatch.util.ParseUtil.findMemberWithSignature(ParseUtil.java:353)
    at org.adoptopenjdk.jitwatch.parser.AbstractLogParser.findMemberWithSignature(AbstractLogParser.java:249)
    at org.adoptopenjdk.jitwatch.parser.AbstractLogParser.handleMember(AbstractLogParser.java:575)
    at org.adoptopenjdk.jitwatch.parser.AbstractLogParser.handleMethodLine(AbstractLogParser.java:478)
    at org.adoptopenjdk.jitwatch.parser.AbstractLogParser.handleTagQueued(AbstractLogParser.java:372)
    at org.adoptopenjdk.jitwatch.parser.hotspot.HotSpotLogParser.handleTag(HotSpotLogParser.java:356)
    at org.adoptopenjdk.jitwatch.parser.hotspot.HotSpotLogParser.parseLogCompilationLines(HotSpotLogParser.java:154)
    at org.adoptopenjdk.jitwatch.parser.hotspot.HotSpotLogParser.parseLogFile(HotSpotLogParser.java:130)
    at org.adoptopenjdk.jitwatch.parser.AbstractLogParser.processLogFile(AbstractLogParser.java:365)
    at org.adoptopenjdk.jitwatch.ui.main.JITWatchUI$1.run(JITWatchUI.java:239)
    at java.lang.Thread.run(Thread.java:748)
11:09:35.093 [JavaFX Application Thread] WARN  o.a.j.c.CompilationUtil - No Task found in Compilation 1431
11:09:35.094 [JavaFX Application Thread] WARN  o.a.j.c.CompilationUtil - Compilation tags for 1431
<task_queued method="com/github/animeshtrivedi/benchmark/ArrowReaderUnsafe consumeInt4 (Lorg/apache/arrow/vector/IntVector;)V" bytes="160" count="2" backedge_count="1972224" stamp="61.128" comment="tiered" hot_count="2" compile_id="1431" iicount="2"/>

<nmethod stub_offset="1168" dependencies_offset="2680" address="0x00007f06752e7590" method="com/github/animeshtrivedi/benchmark/ArrowReaderUnsafe consumeInt4 (Lorg/apache/arrow/vector/IntVector;)V" level="4" count="3" backedge_count="1973248" stamp="61.140" nul_chk_table_offset="2792" scopes_data_offset="1336" iicount="3" handler_table_offset="2696" oops_offset="1248" entry="0x00007f06752e7700" size="2808" scopes_pcs_offset="1704" insts_offset="368" bytes="160" relocation_offset="296" compile_id="1431" compiler="C2"/>

11:09:35.094 [JavaFX Application Thread] WARN  o.a.j.c.CompilationUtil - No Task found in Compilation 1431
chriswhocodes commented 5 years ago

Hi Animesh, I think the simplistic way JITWatch loads classes (in order to discover their methods) using a URLClassloader is causing the problem here. Those VerifyErrors are probably breaking the parse / class model building so I wouldn't expect the results to be correct.

I think it's probably time I swapped this to either use a more advanced class tool like ByteBuddy or build something low level myself.

For now, please can you try to run JITWatch with the -Xverify:none switch to disable verification? That should allow the full class model to be built.

Cheers, Chris

animeshtrivedi commented 5 years ago

Hi Chris - somehow "-Xverify:none" did not make any difference in the behavior of JITWatch from what I have previously reported. One more thing that I noticed now is that JITWatch never finishes the log analysis. It was the same behavior since the beginning (I just noticed it now). The "stop" button is always active and the analysis log never shows something like 

[...]
Finished reading log file.
Finding code suggestions.
[...]

as it does for a good run. For now I can read the assembly from the log file (enough for my purpose). But it would be good if the issue if fixed. Let me know if you need more information or let me run some new experiments.

chriswhocodes commented 5 years ago

Hi Animesh,

Does the log file you previously emailed me exhibit this not finishing parse behaviour?

If I could have an example log file and commit version for the code you used then I'll track this down.

Cheers,

Chris

animeshtrivedi commented 5 years ago

Hi Chris - I have sent (on your gmail id) you a new log from the branch trail commit e9aca7ea01c0ff7151bd2696e3c4269982c447f7.

Thanks for your help and cheers!

chriswhocodes commented 5 years ago

Hi Animesh, I've not been able to reproduce the "not finish parsing" problem but digging into the JITWatch output I've found a bug - JITWatch currently doesn't understand synthetic bridge constructors of the kind described here: http://mail.openjdk.java.net/pipermail/hotspot-compiler-dev/2016-September/024407.html and that is breaking the parse.

I think fixing this first will help in solving your issue.

chriswhocodes commented 5 years ago

Note to self:

modifiers : 
generics  : 
class     : java.util.ArrayList$Itr
returnType: void
memberName: ArrayList$Itr
paramTypes: java.util.ArrayList,java.util.ArrayList$1
java.lang.ClassNotFoundException: java.util.ArrayList$1
    at java.net.URLClassLoader.findClass(URLClassLoader.java:381)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
    at java.lang.Class.forName0(Native Method)
    at java.lang.Class.forName(Class.java:348)
    at org.adoptopenjdk.jitwatch.util.ClassUtil.loadClassWithoutInitialising(ClassUtil.java:50)

javap result for $Itr


Compiled from "ArrayList.java"
class java.util.ArrayList$Itr implements java.util.Iterator<E> {
  int cursor;
  int lastRet;
  int expectedModCount;
  final java.util.ArrayList this$0;
  java.util.ArrayList$Itr(java.util.ArrayList); // this constructor is being called
  public boolean hasNext();
  public E next();
  public void remove();
  public void forEachRemaining(java.util.function.Consumer<? super E>);
  final void checkForComodification();
}

Options - generate a synthetic 2 arg constructor in class model for Itr or identify and drop the ArrayList$1 param?

animeshtrivedi commented 5 years ago

Hi Chris - many thanks for your help. Let me know when I can test the fixed new code. Cheers.

chriswhocodes commented 5 years ago

Hi Animesh, I believe I'm now handling these synthetic bridge constructor args correctly in https://github.com/AdoptOpenJDK/jitwatch/commit/3389a8969d692b4e4750b22872ba40b42b7f55cb I can process your log file without any parse errors and get the correct results in the TriView. Please let me know if that works for you? Cheers, Chris

animeshtrivedi commented 5 years ago

Hi Chris, unfortunately it still is the same behavior as I reported earlier ( I cross checked to make sure I am using the commit you pointed out). I have sent you output from the console as well as in-app (where it shows the progress), and jstack of the JITWatch. If any of this is any help.

Can you tell me which JVM version are you using? and what configuration have you used to parse the file. May be something fishy with that.

chriswhocodes commented 5 years ago

I've been using 8u192 and pulling jars from maven's .m2 folder after compiling your code to make up the classpath for JITWatch.

The jstack trace doesn't indicate JITWatch is stuck in a loop. The only mention of JITWatch in the trace is the handoff to JavaFX's launch method which is confusing as I don't see why it's not completing the parse.

I'll try to use the exact same jars in your log file and see if I can recreate the hang.

chriswhocodes commented 2 years ago

Hi, I'm closing all the issues except for the ones I'm actively working on.