Enable more traces and reduce costs of others#7673
Merged
headius merged 8 commits intojruby:masterfrom Mar 14, 2023
Merged
Conversation
Raising an exception is already a very heavyweight object. By making this always-on, we have fewer trace events that require the --debug flag to capture. Note that this currently acquires a single caller frame in order to provide the file and line in Ruby code where the exception was triggered. This will be of moderate cost on Java 9+ using the StackWalker API, but will require generating a full trace on Java 8. This may impact exception-raising performance, but only when hooks are enabled.
This was marked as needing the frame, but it uses the block's position information to provide file and line rather than getting it from a caller frame.
This change makes the :call, :return, :b_call, and :b_return hook events always available, with zero cost after the JVM has run its optimizations. The enabled and disabled state of these hooks are controlled by an indy MutableCallSite, which normally points at a no-op handle but can be switched to a hook-calling handle. When no hook is active, this will be optimized away in the native code and have no effect on performance. There is a small cost here, in that all method and block bodies will now emit bytecodes to push the context and current module (or current block) onto the stack, in order to indy dispatch to the appropriate call or return operation. This increases bytecode size of all such bodies by 6 bytescodes totalling perhaps 16 bytes, potentially pushing some methods over JVM budgets for JIT or inlining.
Utility method here avoids making three calls from JIT code.
headius
force-pushed
the
always_on_traces
branch
2 times, most recently
from
e55e5b5 to
c7c7f18
Compare
This avoids needing a frame to get the frame class.
headius
force-pushed
the
always_on_traces
branch
from
c7c7f18 to
7a9e6b8
Compare
headius
force-pushed
the
always_on_traces
branch
from
8482054 to
0c1abb0
Compare
kares
reviewed
Feb 20, 2023
Co-authored-by: Karol Bucek <kares@users.noreply.github.com>
Member
Author
|
This was a good experiment, but ultimately we will not enable always-on tracing just yet for a few reasons:
I am doing one additional commit that will move the IR trace instructions for CALL, RETURN, B_CALL, and B_RETURN back behind the --debug flag. We do get the following benefits out of this PR:
|
Member
Author
|
The early non-working prototype of the C_CALL indy wrapper is provided below. The basic idea is to fold the target call into a CallSite for C_CALL hooks that will normally be a no-op. When optimized it should be zero cost and just leverage safepoint. commit b6b8beecf77e39e75c7bb7cf998f4bf7e51311c7
Author: Charles Oliver Nutter <headius@headius.com>
Date: Tue Feb 21 09:59:18 2023 -0600
WIP c_call c_return
diff --git a/core/src/main/java/org/jruby/internal/runtime/methods/InvocationMethodFactory.java b/core/src/main/java/org/jruby/internal/runtime/methods/InvocationMethodFactory.java
index 06d4313503..bbb1c7fb45 100644
--- a/core/src/main/java/org/jruby/internal/runtime/methods/InvocationMethodFactory.java
+++ b/core/src/main/java/org/jruby/internal/runtime/methods/InvocationMethodFactory.java
@@ -253,10 +253,10 @@ public class InvocationMethodFactory extends MethodFactory implements Opcodes {
}
String generatedClassName = CodegenUtils.getAnnotatedBindingClassName(javaMethodName, desc1.declaringClassName, desc1.isStatic, desc1.actualRequired, desc1.optional, descs.size() > 1, desc1.anno.frame());
- if (RubyInstanceConfig.FULL_TRACE_ENABLED) {
+// if (RubyInstanceConfig.FULL_TRACE_ENABLED) {
// in debug mode we append _DBG to class name to force it to regenerate (or use pre-generated debug version)
generatedClassName += "_DBG";
- }
+// }
String generatedClassPath = generatedClassName.replace('.', '/');
DescriptorInfo info = new DescriptorInfo(descs);
@@ -738,7 +738,7 @@ public class InvocationMethodFactory extends MethodFactory implements Opcodes {
invokeCallConfigPre(method, superClass, specificArity, block, callConfig);
}
- final boolean FULL_TRACE_ENABLED = RubyInstanceConfig.FULL_TRACE_ENABLED;
+ final boolean FULL_TRACE_ENABLED = true; //RubyInstanceConfig.FULL_TRACE_ENABLED;
int traceBoolIndex = -1;
if (FULL_TRACE_ENABLED) {
diff --git a/core/src/main/java/org/jruby/ir/runtime/IRRuntimeHelpers.java b/core/src/main/java/org/jruby/ir/runtime/IRRuntimeHelpers.java
index 670f195e8d..f06fb45f28 100644
--- a/core/src/main/java/org/jruby/ir/runtime/IRRuntimeHelpers.java
+++ b/core/src/main/java/org/jruby/ir/runtime/IRRuntimeHelpers.java
@@ -2461,6 +2461,17 @@ public class IRRuntimeHelpers {
}
}
+ @JIT
+ public static void ccallTrace(ThreadContext context, IRubyObject self, RubyEvent event, String name, String filename, int line) {
+ TraceEventManager traceEvents = context.traceEvents;
+ if (traceEvents.hasEventHooks()) {
+ // FIXME: Try and statically generate END linenumber instead of hacking it.
+ int linenumber = line == -1 ? context.getLine() : line;
+
+ traceEvents.callEventHooks(context, event, filename, linenumber, name, self.getType());
+ }
+ }
+
public static void traceRaise(ThreadContext context) {
TraceEventManager traceEvents = context.traceEvents;
if (traceEvents.hasEventHooks()) {
diff --git a/core/src/main/java/org/jruby/ir/targets/JVMVisitor.java b/core/src/main/java/org/jruby/ir/targets/JVMVisitor.java
index d20cf2c202..bc1f367837 100644
--- a/core/src/main/java/org/jruby/ir/targets/JVMVisitor.java
+++ b/core/src/main/java/org/jruby/ir/targets/JVMVisitor.java
@@ -2490,9 +2490,10 @@ public class JVMVisitor extends IRVisitor {
jvmMethod().loadFrameClass();
jvmAdapter().invokedynamic(
- name,
+ "callTrace",
sig(void.class, ThreadContext.class, IRubyObject.class),
CallTraceSite.BOOTSTRAP,
+ name,
traceInstr.getEvent().getName(),
traceInstr.getFilename(),
traceInstr.getLinenumber());
@@ -2504,9 +2505,10 @@ public class JVMVisitor extends IRVisitor {
jvmMethod().loadSelfBlock();
jvmAdapter().invokedynamic(
- name,
+ "callTrace",
sig(void.class, ThreadContext.class, Block.class),
CallTraceSite.BOOTSTRAP,
+ name,
traceInstr.getEvent().getName(),
traceInstr.getFilename(),
traceInstr.getLinenumber());
diff --git a/core/src/main/java/org/jruby/ir/targets/indy/Bootstrap.java b/core/src/main/java/org/jruby/ir/targets/indy/Bootstrap.java
index d4e1f061ba..b287113600 100644
--- a/core/src/main/java/org/jruby/ir/targets/indy/Bootstrap.java
+++ b/core/src/main/java/org/jruby/ir/targets/indy/Bootstrap.java
@@ -67,6 +67,7 @@ import org.jruby.runtime.CompiledIRBlockBody;
import org.jruby.runtime.DynamicScope;
import org.jruby.runtime.Frame;
import org.jruby.runtime.Helpers;
+import org.jruby.runtime.RubyEvent;
import org.jruby.runtime.ThreadContext;
import org.jruby.runtime.builtin.IRubyObject;
import org.jruby.runtime.callsite.CacheEntry;
@@ -1022,7 +1023,7 @@ public class Bootstrap {
return mh;
}
- static MethodHandle buildNativeHandle(InvokeSite site, CacheEntry entry, boolean blockGiven) {
+ static MethodHandle buildNativeHandle(InvokeSite site, CacheEntry entry, IRubyObject self, boolean blockGiven) {
MethodHandle mh = null;
SmartBinder binder = null;
DynamicMethod method = entry.method;
@@ -1101,6 +1102,26 @@ public class Bootstrap {
if (anno != null && anno.frame()) {
mh = InvocationLinker.wrapWithFrameOnly(site.signature, entry.sourceModule, site.name(), mh);
}
+
+ SmartHandle cCallTrace = SmartBinder.from(site.signature)
+ .permute("context", "self")
+ .append("event", RubyEvent.C_CALL)
+ .append(
+ arrayOf("event", "name", "file", "line"),
+ arrayOf(RubyEvent.class, String.class, String.class, int.class),
+ RubyEvent.C_CALL, site.name(), site.file, site.line)
+ .invoke(self.getRuntime().getTraceEvents().getCCallCReturnSite().dynamicInvoker());
+
+ mh = MethodHandles.foldArguments(mh, cCallTrace.handle());
+
+ SmartHandle cReturnTrace = SmartBinder.from(site.signature.prependArg("retval", IRubyObject.class))
+ .permute("context", "self", "retval")
+ .append("event", RubyEvent.C_RETURN)
+ .append(
+ arrayOf("event", "name", "file", "line"),
+ arrayOf(RubyEvent.class, String.class, String.class, int.class),
+ RubyEvent.C_CALL, site.name(), site.file, site.line)
+ .invoke(self.getRuntime().getTraceEvents().getCCallCReturnSite().dynamicInvoker());
}
}
diff --git a/core/src/main/java/org/jruby/ir/targets/indy/CallTraceSite.java b/core/src/main/java/org/jruby/ir/targets/indy/CallTraceSite.java
index b329c14516..778e9046fe 100644
--- a/core/src/main/java/org/jruby/ir/targets/indy/CallTraceSite.java
+++ b/core/src/main/java/org/jruby/ir/targets/indy/CallTraceSite.java
@@ -39,10 +39,10 @@ public class CallTraceSite extends MutableCallSite {
public static final Handle BOOTSTRAP = new Handle(
Opcodes.H_INVOKESTATIC,
p(CallTraceSite.class),
- "bootstrap", sig(CallSite.class, MethodHandles.Lookup.class, String.class, MethodType.class, String.class, String.class, int.class),
+ "bootstrap", sig(CallSite.class, MethodHandles.Lookup.class, String.class, MethodType.class, String.class, String.class, String.class, int.class),
false);
- public static CallSite bootstrap(MethodHandles.Lookup lookup, String name, MethodType type, String event, String file, int line) {
+ public static CallSite bootstrap(MethodHandles.Lookup lookup, String unused, MethodType type, String name, String event, String file, int line) {
CallTraceSite site = new CallTraceSite(type, event, name, file, line);
MethodHandle traceSetup = Binder
.from(type)
diff --git a/core/src/main/java/org/jruby/ir/targets/indy/InvokeSite.java b/core/src/main/java/org/jruby/ir/targets/indy/InvokeSite.java
index f941b08eb9..8dd7a86f25 100644
--- a/core/src/main/java/org/jruby/ir/targets/indy/InvokeSite.java
+++ b/core/src/main/java/org/jruby/ir/targets/indy/InvokeSite.java
@@ -533,7 +533,7 @@ public abstract class InvokeSite extends MutableCallSite {
MethodHandle mh = buildNewInstanceHandle(entry, self);
if (mh == null) mh = buildNotEqualHandle(entry, self);
- if (mh == null) mh = Bootstrap.buildNativeHandle(this, entry, blockGiven);
+ if (mh == null) mh = Bootstrap.buildNativeHandle(this, entry, self, blockGiven);
if (mh == null) mh = buildJavaFieldHandle(this, entry, self);
if (mh == null) mh = Bootstrap.buildIndyHandle(this, entry);
if (mh == null) mh = Bootstrap.buildJittedHandle(this, entry, blockGiven);
diff --git a/core/src/main/java/org/jruby/runtime/TraceEventManager.java b/core/src/main/java/org/jruby/runtime/TraceEventManager.java
index c82a8ea0ec..9d13f5162f 100644
--- a/core/src/main/java/org/jruby/runtime/TraceEventManager.java
+++ b/core/src/main/java/org/jruby/runtime/TraceEventManager.java
@@ -28,6 +28,13 @@ public class TraceEventManager {
.from(void.class, ThreadContext.class, IRubyObject.class, RubyEvent.class, String.class, String.class, int.class)
.drop(1, 5)
.identity();
+ public static final MethodHandle C_TRACE_ON = Binder
+ .from(void.class, ThreadContext.class, IRubyObject.class, RubyEvent.class, String.class, String.class, int.class)
+ .invokeStaticQuiet(LOOKUP, IRRuntimeHelpers.class, "ccallTrace");
+ public static final MethodHandle C_TRACE_OFF = Binder
+ .from(void.class, ThreadContext.class, IRubyObject.class, RubyEvent.class, String.class, String.class, int.class)
+ .drop(1, 5)
+ .identity();
public static final MethodHandle B_TRACE_ON = Binder
.from(void.class, ThreadContext.class, Block.class, RubyEvent.class, String.class, String.class, int.class)
.invokeStaticQuiet(LOOKUP, IRRuntimeHelpers.class, "callTrace");
@@ -44,6 +51,7 @@ public class TraceEventManager {
private final CallTraceFuncHook callTraceFuncHook = new CallTraceFuncHook(null);
private final MutableCallSite callTrace = new MutableCallSite(TRACE_OFF);
+ private final MutableCallSite ccallTrace = new MutableCallSite(C_TRACE_OFF);
private final MutableCallSite bcallTrace = new MutableCallSite(B_TRACE_OFF);
public TraceEventManager(Ruby runtime) {
@@ -112,6 +120,10 @@ public class TraceEventManager {
callTrace.setTarget(TRACE_ON);
}
+ if (hook.isInterestedInEvent(RubyEvent.C_CALL) || hook.isInterestedInEvent(RubyEvent.C_RETURN)) {
+ ccallTrace.setTarget(C_TRACE_ON);
+ }
+
if (hook.isInterestedInEvent(RubyEvent.B_CALL) || hook.isInterestedInEvent(RubyEvent.B_RETURN)) {
bcallTrace.setTarget(B_TRACE_ON);
}
@@ -122,6 +134,10 @@ public class TraceEventManager {
callTrace.setTarget(TRACE_OFF);
}
+ if (hook.isInterestedInEvent(RubyEvent.C_CALL) || hook.isInterestedInEvent(RubyEvent.C_RETURN)) {
+ ccallTrace.setTarget(C_TRACE_OFF);
+ }
+
if (hook.isInterestedInEvent(RubyEvent.B_CALL) || hook.isInterestedInEvent(RubyEvent.B_RETURN)) {
bcallTrace.setTarget(B_TRACE_OFF);
}
@@ -193,6 +209,10 @@ public class TraceEventManager {
return callTrace;
}
+ public MutableCallSite getCCallCReturnSite() {
+ return callTrace;
+ }
+
public MutableCallSite getBCallBReturnSite() {
return bcallTrace;
} |
See jruby#7673 for a discussion of why we are opting not to enable always-on call and return events for now.
headius
changed the title
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
2 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
This PR is an attempt to make more of the trace events (for TracePoint and set_trace_func) always-on, without introducing significant overhead if they are not active (i.e. no enabled tracepoint or trace func).