FFI tracing: trace JNI side to same file FD as Java side in embedded mode

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++;
 	}
 }

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;
 }
 

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

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"),