From f3644b00e0219bdeb047f9d74fc3b62d9bd0ee58 Mon Sep 17 00:00:00 2001
From: stepan <stepan.sindelar@oracle.com>
Date: Mon, 5 Mar 2018 18:00:49 +0100
Subject: [PATCH] Improve RFFI logging
---
.../truffle/r/ffi/impl/common/RFFIUtils.java | 158 ++++++++++--------
.../r/ffi/impl/llvm/TruffleLLVM_Call.java | 3 +-
.../r/ffi/impl/nfi/TruffleNFI_Context.java | 3 +-
.../truffle/r/ffi/processor/FFIProcessor.java | 11 +-
.../r/runtime/data/NativeDataAccess.java | 9 +
.../oracle/truffle/r/runtime/ffi/RFFILog.java | 101 +++++++++++
6 files changed, 210 insertions(+), 75 deletions(-)
create mode 100644 com.oracle.truffle.r.runtime/src/com/oracle/truffle/r/runtime/ffi/RFFILog.java
diff --git a/com.oracle.truffle.r.ffi.impl/src/com/oracle/truffle/r/ffi/impl/common/RFFIUtils.java b/com.oracle.truffle.r.ffi.impl/src/com/oracle/truffle/r/ffi/impl/common/RFFIUtils.java
index e3adbfa00e..b7a447516e 100644
--- a/com.oracle.truffle.r.ffi.impl/src/com/oracle/truffle/r/ffi/impl/common/RFFIUtils.java
+++ b/com.oracle.truffle.r.ffi.impl/src/com/oracle/truffle/r/ffi/impl/common/RFFIUtils.java
@@ -1,5 +1,5 @@
/*
- * Copyright (c) 2014, 2017, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2014, 2018, Oracle and/or its affiliates. All rights reserved.
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
*
* This code is free software; you can redistribute it and/or modify it
@@ -22,22 +22,25 @@
*/
package com.oracle.truffle.r.ffi.impl.common;
-import java.io.FileOutputStream;
-import java.io.IOException;
-import java.nio.file.Path;
import java.util.List;
import com.oracle.truffle.api.CompilerDirectives;
-import com.oracle.truffle.api.CompilerDirectives.CompilationFinal;
import com.oracle.truffle.api.CompilerDirectives.TruffleBoundary;
-import com.oracle.truffle.r.runtime.FastROptions;
+import com.oracle.truffle.api.interop.ForeignAccess;
+import com.oracle.truffle.api.interop.Message;
+import com.oracle.truffle.api.interop.TruffleObject;
+import com.oracle.truffle.api.interop.UnsupportedMessageException;
+import com.oracle.truffle.api.nodes.Node;
import com.oracle.truffle.r.runtime.RInternalError;
-import com.oracle.truffle.r.runtime.Utils;
import com.oracle.truffle.r.runtime.context.RContext;
+import com.oracle.truffle.r.runtime.data.RLanguage;
+import com.oracle.truffle.r.runtime.data.RObject;
import com.oracle.truffle.r.runtime.data.RPairList;
import com.oracle.truffle.r.runtime.data.RSymbol;
import com.oracle.truffle.r.runtime.data.RTypedValue;
+import com.oracle.truffle.r.runtime.data.model.RAbstractVector;
import com.oracle.truffle.r.runtime.ffi.RFFIContext;
+import com.oracle.truffle.r.runtime.ffi.RFFILog;
/**
* Mostly support for tracing R FFI up/down calls. Currently tracing of the arguments to calls is
@@ -49,58 +52,22 @@ import com.oracle.truffle.r.runtime.ffi.RFFIContext;
* that launches RStudio.) and sets the cwd to "/", which is not writeable.
*/
public class RFFIUtils {
- /**
- * Set this to {@code true} when it is not possible to set {@link FastROptions}.
- */
- private static boolean alwaysTrace;
- /**
- * Is set by initialization and caches whether we are tracing.
- */
- @CompilationFinal public static boolean traceEnabled;
-
- public static boolean traceInitialized;
-
- /**
- * Always trace to a file because stdout is problematic for embedded mode.
- */
- private static final String TRACEFILE = "fastr_trace_nativecalls.log";
- private static FileOutputStream traceStream;
-
- /**
- * Handles the initialization of the RFFI downcalls/upcall tracing implementation.
- */
- public static synchronized void initializeTracing() {
- if (!traceInitialized) {
- traceInitialized = true;
- traceEnabled = alwaysTrace || FastROptions.TraceNativeCalls.getBooleanValue();
- if (traceEnabled) {
- if (traceStream == null) {
- initTraceStream();
- }
- }
- }
- }
- private static void initTraceStream() {
- Path tracePath = Utils.getLogPath(TRACEFILE);
- try {
- traceStream = new FileOutputStream(tracePath.toString());
- } catch (IOException ex) {
- System.err.println(ex.getMessage());
- System.exit(1);
- }
- }
+ private static Node isPointerNode;
+ private static Node asPointerNode;
private enum CallMode {
- UP("U"),
- UP_RETURN("UR"),
- DOWN("D"),
- DOWN_RETURN("DR");
+ UP("U", true),
+ UP_RETURN("UR", false),
+ DOWN("D", false),
+ DOWN_RETURN("DR", true);
private final String printName;
+ private final boolean logNativeMirror;
- CallMode(String printName) {
+ CallMode(String printName, boolean logNativeMirror) {
this.printName = printName;
+ this.logNativeMirror = logNativeMirror;
}
}
@@ -125,11 +92,11 @@ public class RFFIUtils {
}
public static boolean traceEnabled() {
- return traceEnabled;
+ return RFFILog.traceEnabled();
}
private static void traceCall(CallMode mode, String name, int depthValue, Object... args) {
- if (traceEnabled) {
+ if (traceEnabled()) {
StringBuilder sb = new StringBuilder();
sb.append("CallRFFI[");
sb.append(mode.printName);
@@ -138,21 +105,13 @@ public class RFFIUtils {
sb.append(']');
sb.append(name);
sb.append('(');
- printArgs(sb, args);
+ printArgs(mode, sb, args);
sb.append(')');
- sb.append(" [ctx:").append(System.identityHashCode(RContext.getInstance()));
- sb.append(",thread:").append(Thread.currentThread().getId()).append(']');
- try {
- traceStream.write(sb.toString().getBytes());
- traceStream.write('\n');
- traceStream.flush();
- } catch (IOException ex) {
- // ignore
- }
+ RFFILog.write(sb.toString());
}
}
- private static void printArgs(StringBuilder sb, Object[] args) {
+ private static void printArgs(CallMode mode, StringBuilder sb, Object[] args) {
boolean first = true;
for (Object arg : args) {
if (first) {
@@ -160,14 +119,38 @@ public class RFFIUtils {
} else {
sb.append(", ");
}
- sb.append(arg == null ? "" : arg.getClass().getSimpleName());
- if (arg instanceof RSymbol) {
- RSymbol symbol = (RSymbol) arg;
- sb.append("(\"" + symbol.getName() + "\")");
+ if (arg == null) {
+ sb.append("null");
+ continue;
+ }
+ sb.append(arg.getClass().getSimpleName()).append('(').append(arg.hashCode());
+ if (arg instanceof TruffleObject && ForeignAccess.sendIsPointer(getIsPointerNode(), (TruffleObject) arg)) {
+ try {
+ sb.append(";ptr:").append(String.valueOf(ForeignAccess.sendAsPointer(getAsPointerNode(), (TruffleObject) arg)));
+ } catch (UnsupportedMessageException e) {
+ throw RInternalError.shouldNotReachHere();
+ }
+ } else if (arg instanceof RSymbol) {
+ sb.append(';').append("\"" + arg.toString() + "\"");
+ } else if (arg instanceof RAbstractVector) {
+ RAbstractVector vec = (RAbstractVector) arg;
+ if (vec.getLength() == 0) {
+ sb.append(";empty");
+ } else {
+ sb.append(";len:" + vec.getLength() + ";data:");
+ for (int i = 0; i < Math.min(3, vec.getLength()); i++) {
+ String str = ((RAbstractVector) arg).getDataAtAsObject(0).toString();
+ str = str.length() > 30 ? str.substring(0, 27) + "..." : str;
+ sb.append(',').append(str);
+ }
+ }
}
- if (!(arg instanceof RTypedValue)) {
- sb.append("(" + arg + ")");
+ // Note: it makes sense to include native mirrors only once they have been create
+ // already
+ if (mode.logNativeMirror && arg instanceof RObject) {
+ sb.append(";" + ((RObject) arg).getNativeMirror());
}
+ sb.append(')');
}
}
@@ -179,6 +162,10 @@ public class RFFIUtils {
static RuntimeException unimplemented(String message) {
CompilerDirectives.transferToInterpreter();
+ if (traceEnabled()) {
+ RFFILog.printf("Error: unimplemented %s", message);
+ RFFILog.printStackTrace();
+ }
throw RInternalError.unimplemented(message);
}
@@ -196,15 +183,44 @@ public class RFFIUtils {
public static <T> T guaranteeInstanceOf(Object x, Class<T> clazz) {
if (x == null) {
CompilerDirectives.transferToInterpreter();
+ if (traceEnabled()) {
+ RFFILog.printf("Error: unexpected type: null instead of " + clazz.getSimpleName());
+ RFFILog.printStackTrace();
+ }
unimplemented("unexpected type: null instead of " + clazz.getSimpleName());
} else if (!clazz.isInstance(x)) {
CompilerDirectives.transferToInterpreter();
+ if (traceEnabled()) {
+ RFFILog.printf("Error: unexpected type: %s is %s instead of %s", x, x.getClass().getSimpleName(), clazz.getSimpleName());
+ RFFILog.printStackTrace();
+ }
unimplemented("unexpected type: " + x + " is " + x.getClass().getSimpleName() + " instead of " + clazz.getSimpleName());
}
return clazz.cast(x);
}
+ public static void logException(Throwable ex) {
+ if (traceEnabled()) {
+ RFFILog.printf("Error: %s, Message: %s", ex.getClass().getSimpleName(), ex.getMessage());
+ RFFILog.printStackTrace();
+ }
+ }
+
private static RFFIContext getContext() {
return RContext.getInstance().getRFFI();
}
+
+ private static Node getIsPointerNode() {
+ if (isPointerNode == null) {
+ isPointerNode = Message.IS_POINTER.createNode();
+ }
+ return isPointerNode;
+ }
+
+ private static Node getAsPointerNode() {
+ if (asPointerNode == null) {
+ asPointerNode = Message.AS_POINTER.createNode();
+ }
+ return asPointerNode;
+ }
}
diff --git a/com.oracle.truffle.r.ffi.impl/src/com/oracle/truffle/r/ffi/impl/llvm/TruffleLLVM_Call.java b/com.oracle.truffle.r.ffi.impl/src/com/oracle/truffle/r/ffi/impl/llvm/TruffleLLVM_Call.java
index 27448accd6..0ee3d5ff4c 100644
--- a/com.oracle.truffle.r.ffi.impl/src/com/oracle/truffle/r/ffi/impl/llvm/TruffleLLVM_Call.java
+++ b/com.oracle.truffle.r.ffi.impl/src/com/oracle/truffle/r/ffi/impl/llvm/TruffleLLVM_Call.java
@@ -53,12 +53,13 @@ import com.oracle.truffle.r.runtime.ffi.CallRFFI;
import com.oracle.truffle.r.runtime.ffi.DLL.SymbolHandle;
import com.oracle.truffle.r.runtime.ffi.NativeCallInfo;
import com.oracle.truffle.r.runtime.ffi.RFFIFactory;
+import com.oracle.truffle.r.runtime.ffi.RFFILog;
import com.oracle.truffle.r.runtime.ffi.RFFIVariables;
final class TruffleLLVM_Call implements CallRFFI {
TruffleLLVM_Call() {
- RFFIUtils.initializeTracing();
+ RFFILog.initializeTracing();
}
static final class ContextStateImpl implements RContext.ContextState {
diff --git a/com.oracle.truffle.r.ffi.impl/src/com/oracle/truffle/r/ffi/impl/nfi/TruffleNFI_Context.java b/com.oracle.truffle.r.ffi.impl/src/com/oracle/truffle/r/ffi/impl/nfi/TruffleNFI_Context.java
index b83771cec9..089c1f6fba 100644
--- a/com.oracle.truffle.r.ffi.impl/src/com/oracle/truffle/r/ffi/impl/nfi/TruffleNFI_Context.java
+++ b/com.oracle.truffle.r.ffi.impl/src/com/oracle/truffle/r/ffi/impl/nfi/TruffleNFI_Context.java
@@ -61,6 +61,7 @@ import com.oracle.truffle.r.runtime.ffi.NativeFunction;
import com.oracle.truffle.r.runtime.ffi.PCRERFFI;
import com.oracle.truffle.r.runtime.ffi.REmbedRFFI;
import com.oracle.truffle.r.runtime.ffi.RFFIContext;
+import com.oracle.truffle.r.runtime.ffi.RFFILog;
import com.oracle.truffle.r.runtime.ffi.RFFIVariables;
import com.oracle.truffle.r.runtime.ffi.StatsRFFI;
import com.oracle.truffle.r.runtime.ffi.ToolsRFFI;
@@ -286,7 +287,7 @@ final class TruffleNFI_Context extends RFFIContext {
@Override
public ContextState initialize(RContext context) {
- RFFIUtils.initializeTracing();
+ RFFILog.initializeTracing();
initializeLock();
if (traceEnabled()) {
traceDownCall("initialize");
diff --git a/com.oracle.truffle.r.ffi.processor/src/com/oracle/truffle/r/ffi/processor/FFIProcessor.java b/com.oracle.truffle.r.ffi.processor/src/com/oracle/truffle/r/ffi/processor/FFIProcessor.java
index 9934ccd6fa..d694878543 100644
--- a/com.oracle.truffle.r.ffi.processor/src/com/oracle/truffle/r/ffi/processor/FFIProcessor.java
+++ b/com.oracle.truffle.r.ffi.processor/src/com/oracle/truffle/r/ffi/processor/FFIProcessor.java
@@ -300,7 +300,7 @@ public final class FFIProcessor extends AbstractProcessor {
w.append(" public Object execute(VirtualFrame frame) {\n");
w.append(" List<Object> arguments = ForeignAccess.getArguments(frame);\n");
w.append(" assert arguments.size() == " + params.size() + " : \"wrong number of arguments passed to " + name + "\";\n");
- w.append(" if (RFFIUtils.traceEnabled) {\n");
+ w.append(" if (RFFIUtils.traceEnabled()) {\n");
w.append(" RFFIUtils.traceUpCall(\"" + name + "\", arguments);\n");
w.append(" }\n");
w.append(" RFFIContext ctx = RContext.getInstance().getStateRFFI();\n");
@@ -328,8 +328,9 @@ public final class FFIProcessor extends AbstractProcessor {
} else {
w.append(";\n");
}
- w.append(" } catch (Exception ex) {\n");
+ w.append(" } catch (Throwable ex) {\n");
w.append(" CompilerDirectives.transferToInterpreter();\n");
+ w.append(" RFFIUtils.logException(ex);\n");
w.append(" handleExceptionNode.execute(ex);\n");
if (returnKind.isPrimitive()) {
w.append(" resultRObj = Integer.valueOf(-1);\n");
@@ -339,11 +340,17 @@ public final class FFIProcessor extends AbstractProcessor {
w.append(" }\n");
w.append(" ctx.afterUpcall(" + canRunGc + ");\n");
if (returnKind == TypeKind.VOID) {
+ w.append(" if (RFFIUtils.traceEnabled()) {\n");
+ w.append(" RFFIUtils.traceUpCallReturn(\"" + name + "\", null);\n");
+ w.append(" }\n");
w.append(" return 0; // void return type\n");
} else {
if (!returnKind.isPrimitive() && m.getAnnotationsByType(RFFICpointer.class).length == 0) {
w.append(" ctx.registerReferenceUsedInNative(resultRObj); \n");
}
+ w.append(" if (RFFIUtils.traceEnabled()) {\n");
+ w.append(" RFFIUtils.traceUpCallReturn(\"" + name + "\", resultRObj);\n");
+ w.append(" }\n");
w.append(" return resultRObj;\n");
}
w.append(" }\n");
diff --git a/com.oracle.truffle.r.runtime/src/com/oracle/truffle/r/runtime/data/NativeDataAccess.java b/com.oracle.truffle.r.runtime/src/com/oracle/truffle/r/runtime/data/NativeDataAccess.java
index 09b82c05c4..a3b1d40cb2 100644
--- a/com.oracle.truffle.r.runtime/src/com/oracle/truffle/r/runtime/data/NativeDataAccess.java
+++ b/com.oracle.truffle.r.runtime/src/com/oracle/truffle/r/runtime/data/NativeDataAccess.java
@@ -42,6 +42,7 @@ import com.oracle.truffle.api.source.SourceSection;
import com.oracle.truffle.r.runtime.RInternalError;
import com.oracle.truffle.r.runtime.RRuntime;
import com.oracle.truffle.r.runtime.context.RContext;
+import com.oracle.truffle.r.runtime.ffi.RFFILog;
import com.oracle.truffle.r.runtime.nodes.RSyntaxNode;
import sun.misc.Unsafe;
@@ -179,6 +180,11 @@ public final class NativeDataAccess {
assert (dataAddress = 0xbadbad) != 0;
}
}
+
+ @Override
+ public String toString() {
+ return "mirror:" + dataAddress;
+ }
}
private static final AtomicLong counter = new AtomicLong(0xdef000000000000L);
@@ -235,6 +241,9 @@ public final class NativeDataAccess {
if (TRACE_MIRROR_ALLOCATION_SITES) {
registerAllocationSite(arg, newMirror);
}
+ if (RFFILog.traceEnabled()) {
+ RFFILog.printf("NativeMirror:" + newMirror.id + "->" + obj.getClass().getSimpleName() + ',' + obj.hashCode());
+ }
return newMirror;
}
diff --git a/com.oracle.truffle.r.runtime/src/com/oracle/truffle/r/runtime/ffi/RFFILog.java b/com.oracle.truffle.r.runtime/src/com/oracle/truffle/r/runtime/ffi/RFFILog.java
new file mode 100644
index 0000000000..5f736dec33
--- /dev/null
+++ b/com.oracle.truffle.r.runtime/src/com/oracle/truffle/r/runtime/ffi/RFFILog.java
@@ -0,0 +1,101 @@
+/*
+ * Copyright (c) 2018, 2018, Oracle and/or its affiliates. All rights reserved.
+ * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
+ *
+ * This code is free software; you can redistribute it and/or modify it
+ * under the terms of the GNU General Public License version 2 only, as
+ * published by the Free Software Foundation.
+ *
+ * This code is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
+ * version 2 for more details (a copy is included in the LICENSE file that
+ * accompanied this code).
+ *
+ * You should have received a copy of the GNU General Public License version
+ * 2 along with this work; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
+ * or visit www.oracle.com if you need additional information or have any
+ * questions.
+ */
+package com.oracle.truffle.r.runtime.ffi;
+
+import java.io.IOException;
+import java.io.PrintWriter;
+import java.nio.file.Path;
+
+import com.oracle.truffle.api.CompilerDirectives.CompilationFinal;
+import com.oracle.truffle.r.runtime.FastROptions;
+import com.oracle.truffle.r.runtime.Utils;
+import com.oracle.truffle.r.runtime.context.RContext;
+
+public class RFFILog {
+ /**
+ * Set this to {@code true} when it is not possible to set {@link FastROptions}.
+ */
+ private static boolean alwaysTrace;
+ /**
+ * Is set by initialization and caches whether we are tracing.
+ */
+ @CompilationFinal public static boolean traceEnabled;
+
+ public static boolean traceInitialized;
+
+ /**
+ * Always trace to a file because stdout is problematic for embedded mode.
+ */
+ private static final String TRACEFILE = "fastr_trace_nativecalls.log";
+ private static PrintWriter traceStream;
+
+ /**
+ * Handles the initialization of the RFFI downcalls/upcall tracing implementation.
+ */
+ public static synchronized void initializeTracing() {
+ if (!traceInitialized) {
+ traceInitialized = true;
+ traceEnabled = alwaysTrace || FastROptions.TraceNativeCalls.getBooleanValue();
+ if (traceEnabled) {
+ if (traceStream == null) {
+ initTraceStream();
+ }
+ }
+ }
+ }
+
+ public static boolean traceEnabled() {
+ return traceEnabled;
+ }
+
+ public static synchronized void write(String value) {
+ assert traceEnabled : "check traceEnabled() before calling RFFILog.write";
+ traceStream.write(value);
+ traceStream.append(" [ctx:").append("" + System.identityHashCode(RContext.getInstance()));
+ traceStream.append(",thread:").append("" + Thread.currentThread().getId()).append(']');
+ traceStream.write('\n');
+ traceStream.flush();
+ }
+
+ public static synchronized void printf(String fmt, Object... args) {
+ assert traceEnabled : "check traceEnabled() before calling RFFILog.printf";
+ traceStream.printf(fmt, args);
+ traceStream.write('\n');
+ traceStream.flush();
+ }
+
+ public static synchronized void printStackTrace() {
+ assert traceEnabled : "check traceEnabled() before calling RFFILog.printStackTrace";
+ new RuntimeException().printStackTrace(traceStream);
+ }
+
+ private static void initTraceStream() {
+ Path tracePath = Utils.getLogPath(TRACEFILE);
+ try {
+ traceStream = new PrintWriter(tracePath.toString());
+ } catch (IOException ex) {
+ System.err.println(ex.getMessage());
+ System.exit(1);
+ }
+ }
+}
--
GitLab