Tracing for developers of native methods.

The existing -verbose:jni is mainly useful for VM developers hacking on the JNI
implementation; this is intended to replace the ad hoc logging developers of
native methods need to write.

Use "-Xint:portable -Xjnitrace:ClassNameSubstring" on the command line. To
trace all native methods (mainly useful for testing the tracing), use
"-Xjnitrace:"; to trace just methods in java.util.regex.Matcher, use
"-Xjnitrace:Matcher" or "-Xjnitrace:Ljava/util/regex/Matcher;" or whatever.
To trace all the methods in Matcher and Pattern, you have to use something
like "-Xjnitrace:java/util/regex/". There's no facility for tracing an
individual method or group of methods because I haven't needed such a thing.

Here's a basic example:

 -> Ljava/nio/charset/Charsets;.toUtf8Bytes([CII)[B (0x400474b8, 0, 5)
 <- Ljava/nio/charset/Charsets;.toUtf8Bytes([CII)[B returned 0x40047548

Here's an example of a non-static native method:

 -> Lorg/apache/harmony/luni/platform/OSFileSystem;.writeImpl(I[BII)J this=0x40012e78 (1, 0x400476d0, 0, 5)
 <- Lorg/apache/harmony/luni/platform/OSFileSystem;.writeImpl(I[BII)J returned 5

Here's an interesting example showing another native method being called, and
an exception being thrown by a native method:

 -> Ljava/lang/VMClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class; (0x400466b8, false)
 -> Ljava/lang/Throwable;.nativeFillInStackTrace()Ljava/lang/Object; ()
 <- Ljava/lang/Throwable;.nativeFillInStackTrace()Ljava/lang/Object; returned 0x400467c8
 <- Ljava/lang/VMClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class; threw Ljava/lang/ClassNotFoundException;

(This functionality needs to be enabled at compile time. A later patch will
address that.)

Change-Id: I6da8930bd4b4f228e07b05cc59a3aea331c5cee1

1 files changed, 111 insertions, 0 deletions

diff --git a/vm/Native.c b/vm/Native.c
index bca45cc62..479fd52e6 100644
--- a/vm/Native.c
+++ b/vm/Native.c
@@ -815,3 +815,114 @@ static void* lookupSharedLibMethod(const Method* method)
     return (void*) dvmHashForeach(gDvm.nativeLibs, findMethodInLib,
         (void*) method);
 }
+
+
+static void appendValue(char type, const JValue value, char* buf, size_t n,
+        bool appendComma)
+{
+    size_t len = strlen(buf);
+    if (len >= n - 32) { // 32 should be longer than anything we could append.
+        buf[len - 1] = '.';
+        buf[len - 2] = '.';
+        buf[len - 3] = '.';
+        return;
+    }
+    char* p = buf + len;
+    switch (type) {
+    case 'B':
+        if (value.b >= 0 && value.b < 10) {
+            sprintf(p, "%d", value.b);
+        } else {
+            sprintf(p, "0x%x (%d)", value.b, value.b);
+        }
+        break;
+    case 'C':
+        if (value.c < 0x7f && value.c >= ' ') {
+            sprintf(p, "U+%x ('%c')", value.c, value.c);
+        } else {
+            sprintf(p, "U+%x", value.c);
+        }
+        break;
+    case 'D':
+        sprintf(p, "%g", value.d);
+        break;
+    case 'F':
+        sprintf(p, "%g", value.f);
+        break;
+    case 'I':
+        sprintf(p, "%d", value.i);
+        break;
+    case 'L':
+        sprintf(p, "0x%x", value.i);
+        break;
+    case 'J':
+        sprintf(p, "%lld", value.j);
+        break;
+    case 'S':
+        sprintf(p, "%d", value.s);
+        break;
+    case 'V':
+        strcpy(p, "void");
+        break;
+    case 'Z':
+        strcpy(p, value.z ? "true" : "false");
+        break;
+    default:
+        sprintf(p, "unknown type '%c'", type);
+        break;
+    }
+
+    if (appendComma) {
+        strcat(p, ", ");
+    }
+}
+
+#define LOGI_NATIVE(...) LOG(LOG_INFO, LOG_TAG "-native", __VA_ARGS__)
+
+void dvmLogNativeMethodEntry(const Method* method, u4* fp)
+{
+    char thisString[32] = { 0 };
+    u4* sp = &fp[method->registersSize - method->insSize];
+    if (!dvmIsStaticMethod(method)) {
+        sprintf(thisString, "this=0x%08x ", *sp++);
+    }
+
+    char argsString[128]= { 0 };
+    const char* desc = &method->shorty[1];
+    while (*desc != '\0') {
+        char argType = *desc++;
+        JValue value;
+        if (argType == 'D' || argType == 'J') {
+            value.j = dvmGetArgLong(sp, 0);
+            sp += 2;
+        } else {
+            value.i = *sp++;
+        }
+        appendValue(argType, value, argsString, sizeof(argsString),
+        *desc != '\0');
+    }
+
+    char* signature = dexProtoCopyMethodDescriptor(&method->prototype);
+    LOGI_NATIVE("-> %s.%s%s %s(%s)", method->clazz->descriptor, method->name,
+            signature, thisString, argsString);
+    free(signature);
+}
+
+void dvmLogNativeMethodExit(const Method* method, Thread* self,
+        const JValue returnValue)
+{
+    char* signature = dexProtoCopyMethodDescriptor(&method->prototype);
+    if (dvmCheckException(self)) {
+        Object* exception = dvmGetException(self);
+        LOGI_NATIVE("<- %s.%s%s threw %s", method->clazz->descriptor,
+                method->name, signature, exception->clazz->descriptor);
+    } else {
+        char returnValueString[128] = { 0 };
+        char returnType = method->shorty[0];
+        appendValue(returnType, returnValue,
+                returnValueString, sizeof(returnValueString), false);
+        LOGI_NATIVE("<- %s.%s%s returned %s", method->clazz->descriptor,
+                method->name, signature, returnValueString);
+    }
+    free(signature);
+}