Log blocking Binder calls to the EventLog.

This mimics what we do already for SQLiteDatabase's db_operation and
ContentProvider's content_query_operation and
content_update_operation:  over a threshold things are always logged,
and under which they're sub-sampled.

Change-Id: Ia0280b9b07b336ee88b17be2a31a7af0fd7c5770

core/java/android/content/EventLogTags.logtags

@@ -4,3 +4,4 @@ option java_package android.content;
 
 52002 content_query_operation (uri|3),(projection|3),(selection|3),(sortorder|3),(time|1|3),(blocking_package|3),(sample_percent|1|6)
 52003 content_update_operation (uri|3),(operation|3),(selection|3),(time|1|3),(blocking_package|3),(sample_percent|1|6)
+52004 binder_operation (descriptor|3),(method_num|1|5),(time|1|3),(blocking_package|3),(sample_percent|1|6)

core/jni/android_util_Binder.cpp

@@ -22,12 +22,15 @@
 
 #include <fcntl.h>
 #include <sys/stat.h>
+#include <sys/types.h>
 #include <stdio.h>
 
 #include <utils/Atomic.h>
 #include <binder/IInterface.h>
 #include <binder/IPCThreadState.h>
 #include <utils/Log.h>
+#include <utils/SystemClock.h>
+#include <cutils/logger.h>
 #include <binder/Parcel.h>
 #include <binder/ProcessState.h>
 #include <binder/IServiceManager.h>
@@ -740,7 +743,7 @@ static jstring android_os_BinderProxy_getInterfaceDescriptor(JNIEnv* env, jobjec
 {
     IBinder* target = (IBinder*) env->GetIntField(obj, gBinderProxyOffsets.mObject);
     if (target != NULL) {
-        String16 desc = target->getInterfaceDescriptor();
+        const String16& desc = target->getInterfaceDescriptor();
         return env->NewString(desc.string(), desc.size());
     }
     jniThrowException(env, "java/lang/RuntimeException",
@@ -759,6 +762,87 @@ static jboolean android_os_BinderProxy_isBinderAlive(JNIEnv* env, jobject obj)
     return alive ? JNI_TRUE : JNI_FALSE;
 }
 
+static int getprocname(pid_t pid, char *buf, size_t len) {
+    char filename[20];
+    FILE *f;
+
+    sprintf(filename, "/proc/%d/cmdline", pid);
+    f = fopen(filename, "r");
+    if (!f) { *buf = '\0'; return 1; }
+    if (!fgets(buf, len, f)) { *buf = '\0'; return 2; }
+    fclose(f);
+    return 0;
+}
+
+static bool push_eventlog_string(char** pos, const char* end, const char* str) {
+    jint len = strlen(str);
+    int space_needed = 1 + sizeof(len) + len;
+    if (end - *pos < space_needed) {
+        LOGW("not enough space for string. remain=%d; needed=%d",
+             (end - *pos), space_needed);
+        return false;
+    }
+    **pos = EVENT_TYPE_STRING;
+    (*pos)++;
+    memcpy(*pos, &len, sizeof(len));
+    *pos += sizeof(len);
+    memcpy(*pos, str, len);
+    *pos += len;
+    return true;
+}
+
+static bool push_eventlog_int(char** pos, const char* end, jint val) {
+    int space_needed = 1 + sizeof(val);
+    if (end - *pos < space_needed) {
+        LOGW("not enough space for int.  remain=%d; needed=%d",
+             (end - *pos), space_needed);
+        return false;
+    }
+    **pos = EVENT_TYPE_INT;
+    (*pos)++;
+    memcpy(*pos, &val, sizeof(val));
+    *pos += sizeof(val);
+    return true;
+}
+
+// From frameworks/base/core/java/android/content/EventLogTags.logtags:
+#define LOGTAG_BINDER_OPERATION 52004
+
+static void conditionally_log_binder_call(int64_t start_millis,
+                                          IBinder* target, jint code) {
+    int duration_ms = static_cast<int>(uptimeMillis() - start_millis);
+
+    int sample_percent;
+    if (duration_ms >= 500) {
+        sample_percent = 100;
+    } else {
+        sample_percent = 100 * duration_ms / 500;
+        if (sample_percent == 0) {
+            return;
+        }
+        if (sample_percent < (random() % 100 + 1)) {
+            return;
+        }
+    }
+
+    char process_name[40];
+    getprocname(getpid(), process_name, sizeof(process_name));
+    String8 desc(target->getInterfaceDescriptor());
+
+    char buf[LOGGER_ENTRY_MAX_PAYLOAD];
+    buf[0] = EVENT_TYPE_LIST;
+    buf[1] = 5;
+    char* pos = &buf[2];
+    char* end = &buf[LOGGER_ENTRY_MAX_PAYLOAD - 1];  // leave room for final \n
+    if (!push_eventlog_string(&pos, end, desc.string())) return;
+    if (!push_eventlog_int(&pos, end, code)) return;
+    if (!push_eventlog_int(&pos, end, duration_ms)) return;
+    if (!push_eventlog_string(&pos, end, process_name)) return;
+    if (!push_eventlog_int(&pos, end, sample_percent)) return;
+    *(pos++) = '\n';   // conventional with EVENT_TYPE_LIST apparently.
+    android_bWriteLog(LOGTAG_BINDER_OPERATION, buf, pos - buf);
+}
+
 static jboolean android_os_BinderProxy_transact(JNIEnv* env, jobject obj,
                                                 jint code, jobject dataObj,
                                                 jobject replyObj, jint flags)
@@ -786,9 +870,20 @@ static jboolean android_os_BinderProxy_transact(JNIEnv* env, jobject obj,
 
     LOGV("Java code calling transact on %p in Java object %p with code %d\n",
             target, obj, code);
+
+    // Only log the binder call duration for things on the Java-level main thread.
+    const bool is_main_thread = (getpid() == gettid());
+    int64_t start_millis;
+    if (is_main_thread) {
+        start_millis = uptimeMillis();
+    }
     //printf("Transact from Java code to %p sending: ", target); data->print();
     status_t err = target->transact(code, *data, reply, flags);
     //if (reply) printf("Transact from Java code to %p received: ", target); reply->print();
+    if (is_main_thread) {
+        conditionally_log_binder_call(start_millis, target, code);
+    }
+
     if (err == NO_ERROR) {
         return JNI_TRUE;
     } else if (err == UNKNOWN_TRANSACTION) {