Can't display assembly of Graal log file

[marschall]

The attached log has been generated with Graal 0.27 from http://www.oracle.com/technetwork/oracle-labs/program-languages/downloads/index.html.
I added hsdis from JDK 8.
The VM options were

-XX:+UnlockDiagnosticVMOptions
-XX:+TraceClassLoading
-XX:+LogCompilation
-XX:+PrintAssembly
-XX:LogFile=compilation8graal-0.5.1.txt

If I click on com.github.marschall.charsequences.CharSequences#uuidFromCharSequence(CharSequence)
I get

Assembly not found. Was -XX:+PrintAssembly option used?

The classes JAR can be found here
https://search.maven.org/remotecontent?filepath=com/github/marschall/charsequences/0.5.1/charsequences-0.5.1-jar-with-test-dependencies.jar
The source JAR can be found here
https://search.maven.org/remotecontent?filepath=com/github/marschall/charsequences/0.5.1/charsequences-0.5.1-sources.jar

This is the log
compilation8graal-0.5.1.txt

[marschall]

This is what's printed on the console
jitwatch-graal-console-log.txt

[marschall]

And if I click on the ´com.github.marschall.charsequences.CharSequences#uuidFromCharSequence(CharSequence)´ method on the console I see

´´´
15:15:33.243 [Thread-8] WARN o.a.j.m.MetaClass - No MetaClass found for inner Class com.github.marschall.charsequences.CharSequences$SubSequenceIterator
15:15:33.244 [Thread-8] WARN o.a.j.m.MetaClass - No MetaClass found for inner Class com.github.marschall.charsequences.CharSequences$SubSequenceIterable
´´´

[chriswhocodes]

Hi Philippe,
Thanks for the detailed bug report!
I think you've found a number of JITWatch bugs here.

There are a few broken XML fragments in the log but I don't think that explains all the errors. I can make JITWatch throw exceptions when navigating the results so there's definitely stuff to fix here.

Will hopefully have some answers in a day or two.

Cheers,

Chris

[chriswhocodes]

Hi Philippe,

Apologies for the delay but I've now figured out what is happening here. I've made a mistake in trying to associate log features with Java major versions instead of HotSpot versions. JITWatch is not taking the correct parsing paths and is not associating the native addresses in the nmethod tags with addresses in the PrintAssembly output.

I will try a fallback parsing approach rather than relying on version numbering in the LogCompilation XML header.

Thanks for your patience,
Chris

[chriswhocodes]

Hi @marschall,

Sorry for the delay - new baby so much less sleep and time for open-source!

I've improved the heuristic for matching nmethod addresses with disassembly when the HotSpot version / log format is not known.

I can now see the C1 assembly for com.github.marschall.charsequences.CharSequences#uuidFromCharSequence but the log doesn't contain the disassembly or the LogCompilation tag for the C2 compilation (it does contain the <task_queued> tag.

I'm not sure if the class files in the jar above match the HotSpot log file as the LogCompilation claims an inline fail on BCI 238 but that does not exist in the javap dump for that method:

<bc code='185' bci='238'/>
<call method='915' instr='invokeinterface'/>
<inline_fail reason='no static binding'/>

       221: lstore_3
       222: iinc          5, 1
       225: goto          194
       228: bipush        24
       230: istore        5
       232: iload         5
       234: bipush        36
       236: if_icmpge     266
       239: aload_0
       240: iload         5
       242: invokeinterface #6,  2            // InterfaceMethod java/lang/CharSequence.charAt:(I)C
       247: invokestatic  #40                 // Method hexDigit:(C)I
       250: istore        6
       252: lload_3
       253: iconst_4

and this means JITWatch can't correctly annotate the bytecode.

I've committed my fixes and will leave this issue open for a bit in case you have any feedback.

Cheers,

Chris

[marschall]

@chriswhocodes no problem, thank you for your work, I'll double check the source match and report back

[marschall]

It's still not working for me. I double checked with this jar https://search.maven.org/remotecontent?filepath=com/github/marschall/charsequences/0.5.3/charsequences-0.5.3-jar-with-test-dependencies.jar and these sources https://search.maven.org/remotecontent?filepath=com/github/marschall/charsequences/0.5.3/charsequences-0.5.3-sources.jar.

I ran the benchmark longer to make sure Graal kicks in resulting in this 63 MB log file
compilation8graal.log.gz

In addtion I get a new issue, Graal jits Graal and Jitwatch can't find the classes, they seem to be under jre/lib/jvmci/graal.jar. This will likely change with JDK 9, there you may want to use lib/jrt-fs.jar.

15:04:43.884 [Thread-4] ERROR o.a.j.m.a.AssemblyProcessor - Could not parse MSP from line: # {method} {0x00007fbbe0aba800} 'getNodes' '()Lorg/graalvm/compiler/graph/iterators/NodeIterable;' in 'org/graalvm/compiler/graph/Graph'
org.adoptopenjdk.jitwatch.model.LogParseException: Could not parse types: Lorg/graalvm/compiler/graph/iterators/NodeIterable;
	at org.adoptopenjdk.jitwatch.util.ParseUtil.getClassTypes(ParseUtil.java:360)
	at org.adoptopenjdk.jitwatch.model.MemberSignatureParts.setParamsAndReturn(MemberSignatureParts.java:375)
	at org.adoptopenjdk.jitwatch.model.MemberSignatureParts.fromAssembly(MemberSignatureParts.java:363)
	at org.adoptopenjdk.jitwatch.model.assembly.AssemblyProcessor.attachAssemblyToMembers(AssemblyProcessor.java:275)
	at org.adoptopenjdk.jitwatch.parser.hotspot.HotSpotLogParser.parseAssemblyLines(HotSpotLogParser.java:152)
	at org.adoptopenjdk.jitwatch.parser.hotspot.HotSpotLogParser.parseLogFile(HotSpotLogParser.java:106)
	at org.adoptopenjdk.jitwatch.parser.AbstractLogParser.processLogFile(AbstractLogParser.java:353)
	at org.adoptopenjdk.jitwatch.ui.main.JITWatchUI$1.run(JITWatchUI.java:235)
	at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.ClassNotFoundException: org.graalvm.compiler.graph.iterators.NodeIterable
	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)
	at org.adoptopenjdk.jitwatch.util.ParseUtil.findClassesForTypeString(ParseUtil.java:796)
	at org.adoptopenjdk.jitwatch.util.ParseUtil.getClassTypes(ParseUtil.java:356)
	... 8 common frames omitted

You can find the current Graal download here http://www.oracle.com/technetwork/oracle-labs/program-languages/downloads/index.html, it's a drop-in replacement for JDK 8 and even runs JITWatch!

[chriswhocodes]

Added support to recognise JVMCI compiler attr.

I can get JITWatch to parse a Graal log from the sandbox if I add the following jars to the sandbox classpath:

graalvm-0.29/jre/lib/jvmci/graal.jar
graalvm-0.29/jre/lib/jvmci/jvmci-api.jar
graalvm-0.29/jre/lib/jvmci/jvmci-hotspot.jar
graalvm-0.29/jre/lib/graalvm/graaljs-launcher.jar
graalvm-0.29/jre/lib/graalvm/graalvm-launchers.jar
graalvm-0.29/jre/lib/graalvm/jline.jar
graalvm-0.29/jre/lib/graalvm/graalpython-launcher.jar
graalvm-0.29/jre/lib/graalvm/launcher-common.jar
graalvm-0.29/jre/lib/jvmci/enterprise-graal.jar
graalvm-0.29/jre/lib/truffle/locator.jar
graalvm-0.29/jre/lib/truffle/truffle-api.jar
graalvm-0.29/jre/lib/truffle/truffle-nfi.jar
graalvm-0.29/jre/lib/truffle/truffle-tck.jar
graalvm-0.29/jre/lib/truffle/truffle-dsl-processor.jar

I think the JVMCI interface is outputting LogCompilation in a different way to HotSpot so I need to look further into this and either support it or report a bug.

[dougxc]

Since the log object implementing -XX:+LogCompilation is a C++ object, Graal does not use it for logging most compilation activity such as inlining given the language barrier. Maybe if you outline what kind of logging JITWatch consumes, we may be able to produce some/all of this output under a different option.

[chriswhocodes]

Hi Doug,
JITWatch is built to digest the nested XML of LogCompilation which is quite nice for representing inlining chains etc.
IBM J9 logs do it a different way with a line-based format that includes lots of IDs and references. I've not had time to fully implement parsers here.
I had some thoughts about suggesting a JSR for a common JIT log format that each JIT compiler / JVM vendor could implement but I think that's probably a pipedream!
Supporting Graal is my number 1 priority for JITWatch this year so I'd be happy to support whatever log information is can emit.
Happy to start some conversations with the team around this :)
Cheers,
Chris

[dougxc]

In terms of logging inlining decisions, Graal doesn't currently have a unified output format that is used by all the various inliners in Graal. We've just had an internal discussion about adding such output and hope to have something soon. However, I can't yet say whether it will be in the XML format produced by -XX:+LogCompilation.

At the moment we have flags like -Dgraal.Log=InliningDecisions and -Dgraal.HotSpotPrintInlining=true but the output is rather unstructured and not all Graal inlining respects these flags.

[chriswhocodes]

I'm closing this issue so we don't spam Philippe with chatter about Graal and JITWatch that's not related to his bug report. New issue is #276.