From ae20ebd47b9a0557c1cf900a80822ed41fbeca43 Mon Sep 17 00:00:00 2001
From: Mick Jordan <mick.jordan@oracle.com>
Date: Mon, 11 Jul 2016 15:34:50 -0700
Subject: [PATCH] FFI tracing: trace JNI side to same file FD as Java side in
embedded mode
---
.../fficall/src/jni/Rembedded.c | 19 +++----
.../fficall/src/jni/rffiutils.c | 51 ++++++++++++++-----
.../fficall/src/jni/rffiutils.h | 11 +++-
.../truffle/r/runtime/ffi/RFFIUtils.java | 20 +++++++-
4 files changed, 75 insertions(+), 26 deletions(-)
diff --git a/com.oracle.truffle.r.native/fficall/src/jni/Rembedded.c b/com.oracle.truffle.r.native/fficall/src/jni/Rembedded.c
index 4bde43ed94..77ce286ad2 100644
--- a/com.oracle.truffle.r.native/fficall/src/jni/Rembedded.c
+++ b/com.oracle.truffle.r.native/fficall/src/jni/Rembedded.c
@@ -43,7 +43,7 @@ typedef jint (JNICALL *JNI_CreateJavaVMFunc)
static void *dlopen_jvmlib(char *libpath) {
void *handle = dlopen(libpath, RTLD_GLOBAL | RTLD_NOW);
if (handle == NULL) {
- printf("Rf_initialize_R: cannot dlopen %s: %s\n", libpath, dlerror());
+ fprintf(stderr, "Rf_initialize_R: cannot dlopen %s: %s\n", libpath, dlerror());
exit(1);
}
return handle;
@@ -108,7 +108,7 @@ int Rf_initialize_R(int argc, char *argv[]) {
// print_environ(environ);
char *r_home = getenv("R_HOME");
if (r_home == NULL) {
- printf("R_HOME must be set\n");
+ fprintf(stderr, "R_HOME must be set\n");
exit(1);
}
struct utsname utsname;
@@ -132,7 +132,7 @@ int Rf_initialize_R(int argc, char *argv[]) {
}
}
if (java_home == NULL) {
- printf("Rf_initialize_R: can't find a JAVA_HOME\n");
+ fprintf(stderr, "Rf_initialize_R: can't find a JAVA_HOME\n");
exit(1);
}
}
@@ -148,13 +148,13 @@ int Rf_initialize_R(int argc, char *argv[]) {
strcat(jlilib_path, "/jre/lib/jli/libjli.dylib");
dlopen_jvmlib(jlilib_path);
} else {
- printf("unsupported OS: %s\n", utsname.sysname);
+ fprintf(stderr, "unsupported OS: %s\n", utsname.sysname);
exit(1);
}
void *vm_handle = dlopen_jvmlib(jvmlib_path);
JNI_CreateJavaVMFunc createJavaVMFunc = (JNI_CreateJavaVMFunc) dlsym(vm_handle, "JNI_CreateJavaVM");
if (createJavaVMFunc == NULL) {
- printf("Rf_initialize_R: cannot find JNI_CreateJavaVM\n");
+ fprintf(stderr, "Rf_initialize_R: cannot find JNI_CreateJavaVM\n");
exit(1);
}
@@ -183,10 +183,11 @@ int Rf_initialize_R(int argc, char *argv[]) {
jint flag = (*createJavaVMFunc)(&javaVM, (void**)
&jniEnv, &vm_args);
if (flag == JNI_ERR) {
- printf("Rf_initEmbeddedR: error creating Java VM, exiting...\n");
+ fprintf(stderr, "Rf_initEmbeddedR: error creating Java VM, exiting...\n");
return 1;
}
+ setEmbedded();
setEnv(jniEnv);
rInterfaceCallbacksClass = checkFindClass(jniEnv, "com/oracle/truffle/r/runtime/RInterfaceCallbacks");
rembeddedClass = checkFindClass(jniEnv, "com/oracle/truffle/r/engine/shell/REmbedded");
@@ -199,7 +200,7 @@ int Rf_initialize_R(int argc, char *argv[]) {
jstring arg = (*jniEnv)->NewStringUTF(jniEnv, argv[i]);
(*jniEnv)->SetObjectArrayElement(jniEnv, argsArray, i, arg);
}
-
+ // Can't TRACE this upcall as system not initialized
R_GlobalContext = malloc(sizeof(struct RCNTXT));
engine = checkRef(jniEnv, (*jniEnv)->CallStaticObjectMethod(jniEnv, rembeddedClass, initializeMethod, argsArray));
initialized++;
@@ -562,10 +563,10 @@ static char *get_classpath(char *r_home) {
// debugging
static void print_environ(char **env) {
- printf("## Environment variables at %p\n", env);
+ fprintf(stdout, "## Environment variables at %p\n", env);
char **e = env;
while (*e != NULL) {
- printf("%s\n", *e);
+ fprintf(stdout, "%s\n", *e);
e++;
}
}
diff --git a/com.oracle.truffle.r.native/fficall/src/jni/rffiutils.c b/com.oracle.truffle.r.native/fficall/src/jni/rffiutils.c
index 549455e5c8..3d88384fb1 100644
--- a/com.oracle.truffle.r.native/fficall/src/jni/rffiutils.c
+++ b/com.oracle.truffle.r.native/fficall/src/jni/rffiutils.c
@@ -23,6 +23,7 @@
#include <rffiutils.h>
#include <string.h>
#include <stdlib.h>
+#include <errno.h>
/*
* All calls pass through one of the call(N) methods in rfficall.c, which carry the JNIEnv value,
@@ -45,8 +46,8 @@ static jmethodID validateMethodID;
static JNIEnv *curenv = NULL;
jmp_buf *callErrorJmpBuf;
-#define DEBUG_CACHE 0
-#define TRACE_COPIES 0
+// default for trace output when enabled
+FILE *traceFile = NULL;
static int alwaysUseGlobal = 0;
#define CACHED_GLOBALREFS_INITIAL_SIZE 64
@@ -68,9 +69,31 @@ static CopiedVector *copiedVectors;
static int copiedVectorsIndex;
static int copiedVectorsLength;
+static int isEmbedded = 0;
+void setEmbedded() {
+ isEmbedded = 1;
+}
void init_utils(JNIEnv *env) {
curenv = env;
+ if (TRACE_ENABLED && traceFile == NULL) {
+ if (!isEmbedded) {
+ traceFile = stdout;
+ } else {
+ jclass RFFIUtilsClass = checkFindClass(env, "com/oracle/truffle/r/runtime/ffi/RFFIUtils");
+ jclass FileDescriptorClass = checkFindClass(env, "java/io/FileDescriptor");
+ jmethodID getTraceFileDescriptorMethodID = checkGetMethodID(env, RFFIUtilsClass, "getTraceFileDescriptor", "()Ljava/io/FileDescriptor;", 1);
+ // ASSUMPTION: FileDescriptor has an "fd" field
+ jobject tfd = (*env)->CallStaticObjectMethod(env, RFFIUtilsClass, getTraceFileDescriptorMethodID);
+ jfieldID fdField = checkGetFieldID(env, FileDescriptorClass, "fd", "I", 0);
+ int fd = (*env)->GetIntField(env, tfd, fdField);
+ traceFile = fdopen(fd, "w");
+ if (traceFile == NULL) {
+ fprintf(stderr, "%s, %d", "failed to fdopen trace file on JNI side\n", errno);
+ exit(1);
+ }
+ }
+ }
RDataFactoryClass = checkFindClass(env, "com/oracle/truffle/r/runtime/data/RDataFactory");
CallRFFIHelperClass = checkFindClass(env, "com/oracle/truffle/r/runtime/ffi/jnr/CallRFFIHelper");
RRuntimeClass = checkFindClass(env, "com/oracle/truffle/r/runtime/RRuntime");
@@ -149,7 +172,7 @@ void releaseCopiedVector(JNIEnv *env, CopiedVector cv) {
}
void callExit(JNIEnv *env) {
-// printf("callExit\n");
+// fprintf(traceFile, "callExit\n");
int i;
for (i = 0; i < copiedVectorsIndex; i++) {
releaseCopiedVector(env, copiedVectors[i]);
@@ -163,14 +186,14 @@ void invalidateCopiedObject(JNIEnv *env, SEXP oldObj) {
CopiedVector cv = copiedVectors[i];
if ((*env)->IsSameObject(env, cv.obj, oldObj)) {
#if TRACE_COPIES
- printf("invalidateCopiedObject(%p): found\n", oldObj);
+ fprintf(traceFile, "invalidateCopiedObject(%p): found\n", oldObj);
#endif
releaseCopiedVector(env, cv);
copiedVectors[i].obj = NULL;
}
}
#if TRACE_COPIES
- printf("invalidateCopiedObject(%p): not found\n", oldObj);
+ fprintf(traceFile, "invalidateCopiedObject(%p): not found\n", oldObj);
#endif
}
@@ -181,20 +204,20 @@ void *findCopiedObject(JNIEnv *env, SEXP x) {
if ((*env)->IsSameObject(env, cv.obj, x)) {
void *data = cv.data;
#if TRACE_COPIES
- printf("findCopiedObject(%p): found %p\n", x, data);
+ fprintf(traceFile, "findCopiedObject(%p): found %p\n", x, data);
#endif
return data;
}
}
#if TRACE_COPIES
- printf("findCopiedObject(%p): not found\n", x);
+ fprintf(traceFile, "findCopiedObject(%p): not found\n", x);
#endif
return NULL;
}
void addCopiedObject(JNIEnv *env, SEXP x, SEXPTYPE type, void *jArray, void *data) {
#if TRACE_COPIES
- printf("addCopiedObject(%p, %p)\n", x, data);
+ fprintf(traceFile, "addCopiedObject(%p, %p)\n", x, data);
#endif
if (copiedVectorsIndex >= copiedVectorsLength) {
int newLength = 2 * copiedVectorsLength;
@@ -213,7 +236,7 @@ void addCopiedObject(JNIEnv *env, SEXP x, SEXPTYPE type, void *jArray, void *dat
copiedVectors[copiedVectorsIndex].jArray = jArray;
copiedVectorsIndex++;
#if TRACE_COPIES
- printf("copiedVectorsIndex: %d\n", copiedVectorsIndex);
+ fprintf(traceFile, "copiedVectorsIndex: %d\n", copiedVectorsIndex);
#endif
}
@@ -225,8 +248,8 @@ static SEXP checkCachedGlobalRef(JNIEnv *env, SEXP obj, int useGlobal) {
break;
}
if ((*env)->IsSameObject(env, ref, obj)) {
-#if DEBUG_CACHE
- printf("gref: cache hit: %d\n", i);
+#if TRACE_REF_CACHE
+ fprintf(traceFile, "gref: cache hit: %d\n", i);
#endif
return ref;
}
@@ -235,8 +258,8 @@ static SEXP checkCachedGlobalRef(JNIEnv *env, SEXP obj, int useGlobal) {
if (useGlobal) {
if (i >= cachedGlobalRefsLength) {
int newLength = cachedGlobalRefsLength * 2;
-#if DEBUG_CACHE
- printf("gref: extending table to %d\n", newLength);
+#if TRACE_REF_CACHE
+ fprintf(traceFile, "gref: extending table to %d\n", newLength);
#endif
SEXP newCachedGlobalRefs = calloc(newLength, sizeof(SEXP));
if (newCachedGlobalRefs == NULL) {
@@ -280,7 +303,7 @@ void validate(SEXP x) {
}
JNIEnv *getEnv() {
-// printf("getEnv()=%p\n", curenv);
+// fprintf(traceFile, "getEnv()=%p\n", curenv);
return curenv;
}
diff --git a/com.oracle.truffle.r.native/fficall/src/jni/rffiutils.h b/com.oracle.truffle.r.native/fficall/src/jni/rffiutils.h
index 784236055a..ee3ee6a5b7 100644
--- a/com.oracle.truffle.r.native/fficall/src/jni/rffiutils.h
+++ b/com.oracle.truffle.r.native/fficall/src/jni/rffiutils.h
@@ -76,13 +76,20 @@ void init_random(JNIEnv *env);
void init_utils(JNIEnv *env);
void init_parse(JNIEnv *env);
+void setEmbedded(void);
+
void setTempDir(JNIEnv *, jstring tempDir);
extern jclass RDataFactoryClass;
extern jclass CallRFFIHelperClass;
extern jclass RRuntimeClass;
+extern FILE *traceFile;
-#define TRACE_UPCALLS 0
+// tracing/debugging support, set to 1 and recompile to enable
+#define TRACE_UPCALLS 1 // trace upcalls
+#define TRACE_REF_CACHE 0 // trace JNI reference cache
+#define TRACE_COPIES 0 // trace copying of internal arrays
+#define TRACE_ENABLED TRACE_UPCALLS || TRACE_REF_CACHE || TRACE_COPIES
#define TARGp "%s(%p)\n"
#define TARGpp "%s(%p, %p)\n"
@@ -94,7 +101,7 @@ extern jclass RRuntimeClass;
#define TARGsdd "%s(\"%s\", %d, %d)\n"
#if TRACE_UPCALLS
-#define TRACE(format, ...) printf(format, __FUNCTION__, __VA_ARGS__)
+#define TRACE(format, ...) fprintf(traceFile, format, __FUNCTION__, __VA_ARGS__)
#else
#define TRACE(format, ...)
#endif
diff --git a/com.oracle.truffle.r.runtime.ffi/src/com/oracle/truffle/r/runtime/ffi/RFFIUtils.java b/com.oracle.truffle.r.runtime.ffi/src/com/oracle/truffle/r/runtime/ffi/RFFIUtils.java
index 0a0dfb4ce5..07e8dfbf1b 100644
--- a/com.oracle.truffle.r.runtime.ffi/src/com/oracle/truffle/r/runtime/ffi/RFFIUtils.java
+++ b/com.oracle.truffle.r.runtime.ffi/src/com/oracle/truffle/r/runtime/ffi/RFFIUtils.java
@@ -22,6 +22,7 @@
*/
package com.oracle.truffle.r.runtime.ffi;
+import java.io.FileDescriptor;
import java.io.FileOutputStream;
import java.io.IOException;
import java.io.PrintStream;
@@ -58,6 +59,7 @@ public class RFFIUtils {
* time in event of multiple concurrent instances (which happens with RStudio).
*/
private static final String tracePathPrefix = "/tmp/fastr_trace_nativecalls.log-";
+ private static FileOutputStream traceFileStream;
private static PrintStream traceStream;
private static void initialize() {
@@ -68,7 +70,8 @@ public class RFFIUtils {
if (traceStream == null) {
String tracePath = tracePathPrefix + Long.toString(System.currentTimeMillis());
try {
- traceStream = new PrintStream(new FileOutputStream(tracePath));
+ traceFileStream = new FileOutputStream(tracePath);
+ traceStream = new PrintStream(traceFileStream);
} catch (IOException ex) {
System.err.println(ex.getMessage());
System.exit(1);
@@ -82,6 +85,21 @@ public class RFFIUtils {
}
}
+ /**
+ * Upcalled from native when tracing to get FD of the {@link #traceFileStream}. Allows the same
+ * fd to be used on both sides of the JNI boundary.
+ */
+ @SuppressWarnings("unused")
+ private static FileDescriptor getTraceFileDescriptor() {
+ try {
+ return traceFileStream.getFD();
+ } catch (IOException ex) {
+ System.err.println(ex.getMessage());
+ System.exit(1);
+ return null;
+ }
+ }
+
private enum CallMode {
UP("Up"),
UP_RETURN("UpReturn"),
--
GitLab