Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

8295537: Enhance TRACE_METHOD_LINKAGE to show the target MethodHandle #10842

Closed

Conversation

iklam
Copy link
Member

@iklam iklam commented Oct 24, 2022

Improve the handling of the java.lang.invoke.MethodHandle.TRACE_METHOD_LINKAGE property to print out the full graph of MethodHandles that are used at a CallSite. This helps us understand how invokedynamic call sites are resolved. For example:

public class StrConcat {
    static String hello = "Hello";
    static String world = "World";
    public static void main(String args[]) {
        System.out.println(hello + world);
        System.out.println(hello + "World");
    }
}

$ java -Djava.lang.invoke.MethodHandle.TRACE_METHOD_LINKAGE=true -cp . StrConcat
linkCallSite StrConcat.main(StrConcat.java:5) java.lang.invoke.StringConcatFactory.makeConcatWithConstants(Lookup,String,MethodType,String,Object[])CallSite/invokeStatic makeConcatWithConstants(String,String)String/BSA1=
linkMethod java.lang.invoke.MethodHandle.invokeExact(Lookup,String,MethodType,String,Object[])CallSite/5
linkMethod => java.lang.invoke.Invokers$Holder.invokeExact_MT(Object,Object,Object,Object,Object,Object,Object)Object/invokeStatic + (Lookup,String,MethodType,String,Object[])CallSite
linkCallSite target class => java.lang.invoke.BoundMethodHandle$Species_L
linkCallSite target => (String,String)String : BMH.reinvoke000_LLL_L=Lambda(a0:L/SpeciesData[L => Species_L],a1:L,a2:L)=>{
    t3:L=Species_L.argL0(a0:L);
    t4:L=MethodHandle.invokeBasic(t3:L,a1:L,a2:L);t4:L}
& BMH=[
  0: MethodHandle = {(Object,Object)String : DMH.invokeStatic000_LLL_L=Lambda(a0:L,a1:L,a2:L)=>{
        t3:L=DirectMethodHandle.internalMemberName(a0:L);
        t4:L=MethodHandle.linkToStatic(a1:L,a2:L,t3:L);t4:L}
    & DMH.MN=java.lang.StringConcatHelper.simpleConcat(Object,Object)String/invokeStatic
  }
]
linkCallSite linkage => java.lang.invoke.Invokers$Holder.linkToTargetMethod(Object,Object,Object)Object/invokeStatic + MethodHandle(String,String)String
HelloWorld
linkCallSite StrConcat.main(StrConcat.java:6) java.lang.invoke.StringConcatFactory.makeConcatWithConstants(Lookup,String,MethodType,String,Object[])CallSite/invokeStatic makeConcatWithConstants(String)String/BSA1=World
linkCallSite target class => java.lang.invoke.BoundMethodHandle$Species_LL
linkCallSite target => (String)String : invoke000_LL_L=Lambda(a0:L/SpeciesData[LL => BoundMethodHandle$Species_LL],a1:L)=>{
    t2:L=BoundMethodHandle$Species_LL.argL1(a0:L);
    t3:L=BoundMethodHandle$Species_LL.argL0(a0:L);
    t4:L=MethodHandle.invokeBasic(t3:L,a1:L,t2:L);t4:L}
& BMH=[
  0: MethodHandle = {(Object,Object)String : DMH.invokeStatic000_LLL_L=Lambda(a0:L,a1:L,a2:L)=>{
        t3:L=DirectMethodHandle.internalMemberName(a0:L);
        t4:L=MethodHandle.linkToStatic(a1:L,a2:L,t3:L);t4:L}
    & DMH.MN=java.lang.StringConcatHelper.simpleConcat(Object,Object)String/invokeStatic
  }
  1: ( World )
]
linkCallSite linkage => java.lang.invoke.Invokers$Holder.linkToTargetMethod(Object,Object)Object/invokeStatic + MethodHandle(String)String
HelloWorld

More complex examples are in the JBS bug report


Progress

  • Change must be properly reviewed (1 review required, with at least 1 Reviewer)
  • Change must not contain extraneous whitespace
  • Commit message must refer to an issue

Issue

  • JDK-8295537: Enhance TRACE_METHOD_LINKAGE to show the target MethodHandle

Reviewers

Reviewing

Using git

Checkout this PR locally:
$ git fetch https://git.openjdk.org/jdk pull/10842/head:pull/10842
$ git checkout pull/10842

Update a local copy of the PR:
$ git checkout pull/10842
$ git pull https://git.openjdk.org/jdk pull/10842/head

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 10842

View PR using the GUI difftool:
$ git pr show -t 10842

Using diff file

Download this PR as a diff file:
https://git.openjdk.org/jdk/pull/10842.diff

@bridgekeeper
Copy link

bridgekeeper bot commented Oct 24, 2022

👋 Welcome back iklam! A progress list of the required criteria for merging this PR into master will be added to the body of your pull request. There are additional pull request commands available for use with this pull request.

@openjdk openjdk bot added the rfr Pull request is ready for review label Oct 24, 2022
@openjdk
Copy link

openjdk bot commented Oct 24, 2022

@iklam The following label will be automatically applied to this pull request:

  • core-libs

When this pull request is ready to be reviewed, an "RFR" email will be sent to the corresponding mailing list. If you would like to change these labels, use the /label pull request command.

@openjdk openjdk bot added the core-libs core-libs-dev@openjdk.org label Oct 24, 2022
@mlbridge
Copy link

mlbridge bot commented Oct 24, 2022

Webrevs

@dholmes-ora
Copy link
Member

/csr needed

@openjdk openjdk bot added the csr Pull request needs approved CSR before integration label Oct 24, 2022
@openjdk
Copy link

openjdk bot commented Oct 24, 2022

@dholmes-ora has indicated that a compatibility and specification (CSR) request is needed for this pull request.

@iklam please create a CSR request for issue JDK-8295537 with the correct fix version. This pull request cannot be integrated until the CSR request is approved.

@dholmes-ora
Copy link
Member

/csr notneeded

These tracing flags are considered "diagnostic" and don't need a CSR request. Sorry for the noise.

@openjdk
Copy link

openjdk bot commented Oct 24, 2022

@dholmes-ora usage: /csr [needed|unneeded], requires that the issue the pull request refers to links to an approved CSR request.

@dholmes-ora
Copy link
Member

/csr unneeded

@openjdk openjdk bot removed the csr Pull request needs approved CSR before integration label Oct 24, 2022
@openjdk
Copy link

openjdk bot commented Oct 24, 2022

@dholmes-ora determined that a CSR request is not needed for this pull request.

if (indentLevel <= 0) {
return "";
}
return new String(new char[indentLevel*4]).replace('\0', ' ');
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I guess this could be:

Suggested change
return new String(new char[indentLevel*4]).replace('\0', ' ');
return " ".repeat(indentLevel);

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Alternatively, I was gonna suggest not having a prefix/indentLevel and instead calling String::indent at the use site. But, that method uses streams/lambdas, so there might be boostrap cycle issues.

@@ -116,6 +176,16 @@ abstract sealed class CallSite permits ConstantCallSite, MutableCallSite, Volati
CallSite(MethodHandle target) {
target.type(); // null check
this.target = target;
if (MethodHandleStatics.TRACE_CALLSITE) {
Copy link
Member

@JornVernee JornVernee Oct 25, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This doesn't seem like the right place to put this. Anyone can indirectly extend CallSite, by extending e.g. MutableCallSite, but this code seems to assume that the call is going through MethodHandleNatives.linkCallSite? I suggest putting any tracing around that area. Both the target method handle, and the BSM are available at that point in the code as well.

I also note that there's already a TRACE_METHOD_LINKAGE flag as well, which does some tracing of call site linking. Maybe that option could be enhanced instead of adding a new one?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for the suggestion! I removed the new property and just piggyback on TRACE_METHOD_LINKAGE. I also moved the tracing code into MethodHandleNatives.linkCallSiteXXX, and improved the existing code a bit to print out the line number of the call site.

Here's what it looks like now:

$ java -Djava.lang.invoke.MethodHandle.TRACE_METHOD_LINKAGE=true -cp . StrConcat
[...]
linkCallSite StrConcat.main(StrConcat.java:6) java.lang.invoke.StringConcatFactory.makeConcatWithConstants(Lookup,String,MethodType,String,Object[])CallSite/invokeStatic makeConcatWithConstants(String)String/BSA1=World
linkCallSite target class => java.lang.invoke.BoundMethodHandle$Species_LL
linkCallSite target => (String)String : invoke001_LL_L=Lambda(a0:L/SpeciesData[LL => BoundMethodHandle$Species_LL],a1:L)=>{
    t2:L=BoundMethodHandle$Species_LL.argL1(a0:L);
    t3:L=BoundMethodHandle$Species_LL.argL0(a0:L);
    t4:L=MethodHandle.invokeBasic(t3:L,a1:L,t2:L);t4:L}
& BMH=[
  0: MethodHandle = {(Object,Object)String : DMH.invokeStatic000_LLL_L=Lambda(a0:L,a1:L,a2:L)=>{
        t3:L=DirectMethodHandle.internalMemberName(a0:L);
        t4:L=MethodHandle.linkToStatic(a1:L,a2:L,t3:L);t4:L}
    & DMH.MN=java.lang.StringConcatHelper.simpleConcat(Object,Object)String/invokeStatic
  }
  1: ( World )
]
linkCallSite linkage => java.lang.invoke.Invokers$Holder.linkToTargetMethod(Object,Object)Object/invokeStatic + MethodHandle(String)String
HelloWorld

Copy link
Member

@JornVernee JornVernee left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The changes look good, but I have some more comments.

Comment on lines 310 to 329
String callerName = caller.getName();
String[] callerInfo = new String[] {callerName};
StackWalker.getInstance().walk(new Function<Stream<StackWalker.StackFrame>, Object>() {
// We use inner classes (instead of stream/lambda) to avoid triggering
// further invokedynamic resolution, which would cause infinite recursion.
// It's OK to use + for string concat, because java.base is compiled without
// the use of indy string concat.
@Override
public Object apply(Stream<StackWalker.StackFrame> s) {
s.forEach(new Consumer<StackWalker.StackFrame>() {
@Override
public void accept(StackWalker.StackFrame f) {
if (!"java.lang.invoke.MethodHandleNatives".equals(f.getClassName()) && callerInfo[0] == callerName) {
callerInfo[0] = f.toStackTraceElement().toString();
}
}
});
return null;
}
});
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not sure about this condition. It seems like callerInfo[0] == callerName will always be true at first, and then it gets overwritten by the stack trace element toString, so in effect it only picks up the first non-MethodHandleNatives caller? I think it could be clearer to use filter + findFirst to get the caller's StackFrame (that has the additional benefit of short-circuiting), and then convert to a String from there.

Also, please move the code that gets the caller info out-of-line to a helper method, since it's quite wordy.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Alternatively, maybe you could just dump the whole stack trace here (e.g. with Thread.dumpStack()), since it might be useful to see which code path triggers resolution of a call site as well. That would also include the line number of the caller.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is it possible to use filter/findfirst without using lambdas? I want to avoid recursion inside the tracing code.

I am not sure about dumping the call stack. It seems an overkill and not useful in most cases. It’s easier to rebuild the JDK and add Thread.dumpStack() in the rare occasion that you need to do this.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is it possible to use filter/findfirst without using lambdas? I want to avoid recursion inside the tracing code.

You could do this I believe (if I've eye-balled that correctly :)):

Suggested change
String callerName = caller.getName();
String[] callerInfo = new String[] {callerName};
StackWalker.getInstance().walk(new Function<Stream<StackWalker.StackFrame>, Object>() {
// We use inner classes (instead of stream/lambda) to avoid triggering
// further invokedynamic resolution, which would cause infinite recursion.
// It's OK to use + for string concat, because java.base is compiled without
// the use of indy string concat.
@Override
public Object apply(Stream<StackWalker.StackFrame> s) {
s.forEach(new Consumer<StackWalker.StackFrame>() {
@Override
public void accept(StackWalker.StackFrame f) {
if (!"java.lang.invoke.MethodHandleNatives".equals(f.getClassName()) && callerInfo[0] == callerName) {
callerInfo[0] = f.toStackTraceElement().toString();
}
}
});
return null;
}
});
String callerName = caller.getName();
String callerInfo = StackWalker.getInstance().walk(new Function<Stream<StackWalker.StackFrame>, String>() {
// We use inner classes (instead of stream/lambda) to avoid triggering
// further invokedynamic resolution, which would cause infinite recursion.
// It's OK to use + for string concat, because java.base is compiled without
// the use of indy string concat.
@Override
public String apply(Stream<StackWalker.StackFrame> s) {
return s.filter(new Predicate<StackWalker.StackFrame>() {
@Override
public boolean test(StackWalker.StackFrame f) {
return callerName.equals(f.getClassName());
}
}).findFirst().get().toStackTraceElement().toString();
}
});

I am not sure about dumping the call stack. It seems an overkill and not useful in most cases. It’s easier to rebuild the JDK and add Thread.dumpStack() in the rare occasion that you need to do this.

Fair enough.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Or, maybe it's easier to use Thread.currentThread().getStackTrace() and avoid messing around with streams altogether.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I ended up using Thread.currentThread().getStackTrace() and the code is much cleaner. Performance isn't important anyway. Stream.filter() doesn't work because it uses a Lambda in <clinit>:

java.lang.NullPointerException: Cannot invoke "java.util.stream.TerminalOp.getOpFlags()" because "terminalOp" is null
        at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
        at java.base/java.util.stream.ReferencePipeline.findFirst(ReferencePipeline.java:647)
        at java.base/java.lang.invoke.MethodHandleNatives$1.apply(MethodHandleNatives.java:328)
        at java.base/java.lang.invoke.MethodHandleNatives$1.apply(MethodHandleNatives.java:315)
        at java.base/java.lang.StackStreamFactory$StackFrameTraverser.consumeFrames(StackStreamFactory.java:586)
        at java.base/java.lang.StackStreamFactory$AbstractStackWalker.doStackWalk(StackStreamFactory.java:324)
        at java.base/java.lang.StackStreamFactory$AbstractStackWalker.callStackWalk(Native Method)
        at java.base/java.lang.StackStreamFactory$AbstractStackWalker.beginStackWalk(StackStreamFactory.java:410)
        at java.base/java.lang.StackStreamFactory$AbstractStackWalker.walkHelper(StackStreamFactory.java:261)
        at java.base/java.lang.StackStreamFactory$AbstractStackWalker.walk(StackStreamFactory.java:253)
        at java.base/java.lang.StackWalker.walk(StackWalker.java:589)
        at java.base/java.lang.invoke.MethodHandleNatives.linkCallSiteTracing(MethodHandleNatives.java:315)
        at java.base/java.lang.invoke.MethodHandleNatives.linkCallSite(MethodHandleNatives.java:275)
        at java.base/java.util.stream.FindOps$FindSink$OfRef.<clinit>(FindOps.java:198)
        at java.base/java.util.stream.FindOps.makeRef(FindOps.java:60)
        at java.base/java.util.stream.ReferencePipeline.findFirst(ReferencePipeline.java:647)
        at java.base/java.lang.invoke.MethodHandleNatives$1.apply(MethodHandleNatives.java:328)
        at java.base/java.lang.invoke.MethodHandleNatives$1.apply(MethodHandleNatives.java:315)
        at java.base/java.lang.StackStreamFactory$StackFrameTraverser.consumeFrames(StackStreamFactory.java:586)
        at java.base/java.lang.StackStreamFactory$AbstractStackWalker.doStackWalk(StackStreamFactory.java:324)
        at java.base/java.lang.StackStreamFactory$AbstractStackWalker.callStackWalk(Native Method)
        at java.base/java.lang.StackStreamFactory$AbstractStackWalker.beginStackWalk(StackStreamFactory.java:410)
        at java.base/java.lang.StackStreamFactory$AbstractStackWalker.walkHelper(StackStreamFactory.java:261)
        at java.base/java.lang.StackStreamFactory$AbstractStackWalker.walk(StackStreamFactory.java:253)
        at java.base/java.lang.StackWalker.walk(StackWalker.java:589)
        at java.base/java.lang.invoke.MethodHandleNatives.linkCallSiteTracing(MethodHandleNatives.java:315)
        at java.base/java.lang.invoke.MethodHandleNatives.linkCallSite(MethodHandleNatives.java:275)
        at java.base/jdk.internal.module.SystemModuleFinders$1.find(SystemModuleFinders.java:216)
        at java.base/jdk.internal.module.ModuleBootstrap.boot2(ModuleBootstrap.java:260)
        at java.base/jdk.internal.module.ModuleBootstrap.boot(ModuleBootstrap.java:174)
        at java.base/java.lang.System.initPhase2(System.java:2214)

System.out.println("linkCallSite "+caller.getName()+" "+
String callerName = caller.getName();
String[] callerInfo = new String[] {callerName};
StackWalker.getInstance().walk(new Function<Stream<StackWalker.StackFrame>, Object>() {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You can call StackWalker.getInstance(Option.RETAIN_CLASS_REFERENCE) to retain Class instance in StackFrame such that you can compare Class instance rather than class name.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The StackWalker API depends on Streams, which is likely to have lambdas in its implementation. To avoid the possibility of bootstrap problems, I have changed the code to use Thread.currentThread().getStackTrace(), which is used by Throwable.printStackTrace(). Since printStackTrace() is supposed to be useable at very early bootstrap stages, we are sure no lambdas will be used.

Unfortunately getStackTrace() doesn't return the Class object, so I have to use the class's name.

Copy link
Member

@JornVernee JornVernee left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Very nice, Thanks!

@openjdk
Copy link

openjdk bot commented Oct 26, 2022

@iklam This change now passes all automated pre-integration checks.

ℹ️ This project also has non-automated pre-integration requirements. Please see the file CONTRIBUTING.md for details.

After integration, the commit message for the final commit will be:

8295537: Enhance TRACE_METHOD_LINKAGE to show the target MethodHandle

Reviewed-by: jvernee, redestad, mchung

You can use pull request commands such as /summary, /contributor and /issue to adjust it as needed.

At the time when this comment was updated there had been 3 new commits pushed to the master branch:

  • b8ad6cd: 8294461: wrong effectively final determination by javac
  • d667895: 8294399: (ch) Refactor some methods out of sun.nio.ch.UnixFileDispatcherImpl
  • 628820f: 8283093: JMX connections should default to using an ObjectInputFilter

Please see this link for an up-to-date comparison between the source branch of this pull request and the master branch.
As there are no conflicts, your changes will automatically be rebased on top of these commits when integrating. If you prefer to avoid this automatic rebasing, please check the documentation for the /integrate command for further details.

➡️ To integrate this PR with the above commit message to the master branch, type /integrate in a new comment.

@openjdk openjdk bot added the ready Pull request is ready to be integrated label Oct 26, 2022
@openjdk openjdk bot removed the ready Pull request is ready to be integrated label Oct 27, 2022
@iklam iklam changed the title 8295537: Debug tracing for resolved java.lang.invoke.CallSite 8295537: Enhance TRACE_METHOD_LINKAGE to show the target MethodHandle Oct 27, 2022
@openjdk openjdk bot added the ready Pull request is ready to be integrated label Oct 27, 2022
@iklam
Copy link
Member Author

iklam commented Oct 27, 2022

Thanks @cl4es @JornVernee @mlchung for the review.
/integrate

@openjdk
Copy link

openjdk bot commented Oct 27, 2022

Going to push as commit fd668dc.
Since your change was applied there have been 7 commits pushed to the master branch:

  • 182c215: 8295994: Remove left over InetAddressContainer class
  • 78763fc: 8295000: java/util/Formatter/Basic test cleanup
  • 907d583: 8295323: Unnecessary HashTable usage in StyleSheet
  • 2157145: 8293858: Change PKCS7 code to use default SecureRandom impl instead of SHA1PRNG
  • b8ad6cd: 8294461: wrong effectively final determination by javac
  • d667895: 8294399: (ch) Refactor some methods out of sun.nio.ch.UnixFileDispatcherImpl
  • 628820f: 8283093: JMX connections should default to using an ObjectInputFilter

Your commit was automatically rebased without conflicts.

@openjdk openjdk bot added the integrated Pull request has been integrated label Oct 27, 2022
@openjdk openjdk bot closed this Oct 27, 2022
@openjdk openjdk bot removed ready Pull request is ready to be integrated rfr Pull request is ready for review labels Oct 27, 2022
@openjdk
Copy link

openjdk bot commented Oct 27, 2022

@iklam Pushed as commit fd668dc.

💡 You may see a message that your pull request was closed with unmerged commits. This can be safely ignored.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
core-libs core-libs-dev@openjdk.org integrated Pull request has been integrated
Development

Successfully merging this pull request may close these issues.

5 participants