1 files changed, 268 insertions, 0 deletions
diff --git a/liblog/tests/liblog_benchmark.cpp b/liblog/tests/liblog_benchmark.cpp
new file mode 100644
index 0000000..19406fb
--- /dev/null
+++ b/liblog/tests/liblog_benchmark.cpp
@@ -0,0 +1,268 @@
+/*
+ * Copyright (C) 2013-2014 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#include <sys/socket.h>
+#include <cutils/sockets.h>
+#include <log/log.h>
+#include <log/logger.h>
+#include <log/log_read.h>
+
+#include "benchmark.h"
+
+// enhanced version of LOG_FAILURE_RETRY to add support for EAGAIN and
+// non-syscall libs. Since we are benchmarking, or using this in the emergency
+// signal to stuff a terminating code, we do NOT want to introduce
+// a syscall or usleep on EAGAIN retry.
+#define LOG_FAILURE_RETRY(exp) ({  \
+    typeof (exp) _rc;              \
+    do {                           \
+        _rc = (exp);               \
+    } while (((_rc == -1)          \
+           && ((errno == EINTR)    \
+            || (errno == EAGAIN))) \
+          || (_rc == -EINTR)       \
+          || (_rc == -EAGAIN));    \
+    _rc; })
+
+/*
+ *	Measure the fastest rate we can reliabley stuff print messages into
+ * the log at high pressure. Expect this to be less than double the process
+ * wakeup time (2ms?)
+ */
+static void BM_log_maximum_retry(int iters) {
+    StartBenchmarkTiming();
+
+    for (int i = 0; i < iters; ++i) {
+        LOG_FAILURE_RETRY(
+            __android_log_print(ANDROID_LOG_INFO,
+                                "BM_log_maximum_retry", "%d", i));
+    }
+
+    StopBenchmarkTiming();
+}
+BENCHMARK(BM_log_maximum_retry);
+
+/*
+ *	Measure the fastest rate we can stuff print messages into the log
+ * at high pressure. Expect this to be less than double the process wakeup
+ * time (2ms?)
+ */
+static void BM_log_maximum(int iters) {
+    StartBenchmarkTiming();
+
+    for (int i = 0; i < iters; ++i) {
+        __android_log_print(ANDROID_LOG_INFO, "BM_log_maximum", "%d", i);
+    }
+
+    StopBenchmarkTiming();
+}
+BENCHMARK(BM_log_maximum);
+
+/*
+ *	Measure the time it takes to submit the android logging call using
+ * discrete acquisition under light load. Expect this to be a pair of
+ * syscall periods (2us).
+ */
+static void BM_clock_overhead(int iters) {
+    for (int i = 0; i < iters; ++i) {
+       StartBenchmarkTiming();
+       StopBenchmarkTiming();
+    }
+}
+BENCHMARK(BM_clock_overhead);
+
+/*
+ *	Measure the time it takes to submit the android logging call using
+ * discrete acquisition under light load. Expect this to be a dozen or so
+ * syscall periods (40us).
+ */
+static void BM_log_overhead(int iters) {
+    for (int i = 0; i < iters; ++i) {
+       StartBenchmarkTiming();
+       __android_log_print(ANDROID_LOG_INFO, "BM_log_overhead", "%d", i);
+       StopBenchmarkTiming();
+       usleep(1000);
+    }
+}
+BENCHMARK(BM_log_overhead);
+
+static void caught_latency(int signum)
+{
+    unsigned long long v = 0xDEADBEEFA55A5AA5ULL;
+
+    LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
+}
+
+static unsigned long long caught_convert(char *cp)
+{
+    unsigned long long l = cp[0] & 0xFF;
+    l |= (unsigned long long) (cp[1] & 0xFF) << 8;
+    l |= (unsigned long long) (cp[2] & 0xFF) << 16;
+    l |= (unsigned long long) (cp[3] & 0xFF) << 24;
+    l |= (unsigned long long) (cp[4] & 0xFF) << 32;
+    l |= (unsigned long long) (cp[5] & 0xFF) << 40;
+    l |= (unsigned long long) (cp[6] & 0xFF) << 48;
+    l |= (unsigned long long) (cp[7] & 0xFF) << 56;
+    return l;
+}
+
+static const int alarm_time = 3;
+
+/*
+ *	Measure the time it takes for the logd posting call to acquire the
+ * timestamp to place into the internal record. Expect this to be less than
+ * 4 syscalls (3us).
+ */
+static void BM_log_latency(int iters) {
+    pid_t pid = getpid();
+
+    struct logger_list * logger_list = android_logger_list_open(LOG_ID_EVENTS,
+        O_RDONLY, 0, pid);
+
+    if (!logger_list) {
+        fprintf(stderr, "Unable to open events log: %s\n", strerror(errno));
+        exit(EXIT_FAILURE);
+    }
+
+    signal(SIGALRM, caught_latency);
+    alarm(alarm_time);
+
+    for (int j = 0, i = 0; i < iters && j < 10*iters; ++i, ++j) {
+        log_time ts;
+        LOG_FAILURE_RETRY((
+            clock_gettime(CLOCK_REALTIME, &ts),
+            android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts))));
+
+        for (;;) {
+            log_msg log_msg;
+            int ret = android_logger_list_read(logger_list, &log_msg);
+            alarm(alarm_time);
+
+            if (ret <= 0) {
+                iters = i;
+                break;
+            }
+            if ((log_msg.entry.len != (4 + 1 + 8))
+             || (log_msg.id() != LOG_ID_EVENTS)) {
+                continue;
+            }
+
+            char* eventData = log_msg.msg();
+
+            if (eventData[4] != EVENT_TYPE_LONG) {
+                continue;
+            }
+            log_time tx(eventData + 4 + 1);
+            if (ts != tx) {
+                if (0xDEADBEEFA55A5AA5ULL == caught_convert(eventData + 4 + 1)) {
+                    iters = i;
+                    break;
+                }
+                continue;
+            }
+
+            uint64_t start = ts.nsec();
+            uint64_t end = log_msg.nsec();
+            if (end >= start) {
+                StartBenchmarkTiming(start);
+                StopBenchmarkTiming(end);
+            } else {
+                --i;
+            }
+            break;
+        }
+    }
+
+    signal(SIGALRM, SIG_DFL);
+    alarm(0);
+
+    android_logger_list_free(logger_list);
+}
+BENCHMARK(BM_log_latency);
+
+static void caught_delay(int signum)
+{
+    unsigned long long v = 0xDEADBEEFA55A5AA6ULL;
+
+    LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
+}
+
+/*
+ *	Measure the time it takes for the logd posting call to make it into
+ * the logs. Expect this to be less than double the process wakeup time (2ms).
+ */
+static void BM_log_delay(int iters) {
+    pid_t pid = getpid();
+
+    struct logger_list * logger_list = android_logger_list_open(LOG_ID_EVENTS,
+        O_RDONLY, 0, pid);
+
+    if (!logger_list) {
+        fprintf(stderr, "Unable to open events log: %s\n", strerror(errno));
+        exit(EXIT_FAILURE);
+    }
+
+    signal(SIGALRM, caught_delay);
+    alarm(alarm_time);
+
+    StartBenchmarkTiming();
+
+    for (int i = 0; i < iters; ++i) {
+        log_time ts(CLOCK_REALTIME);
+
+        LOG_FAILURE_RETRY(
+            android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts)));
+
+        for (;;) {
+            log_msg log_msg;
+            int ret = android_logger_list_read(logger_list, &log_msg);
+            alarm(alarm_time);
+
+            if (ret <= 0) {
+                iters = i;
+                break;
+            }
+            if ((log_msg.entry.len != (4 + 1 + 8))
+             || (log_msg.id() != LOG_ID_EVENTS)) {
+                continue;
+            }
+
+            char* eventData = log_msg.msg();
+
+            if (eventData[4] != EVENT_TYPE_LONG) {
+                continue;
+            }
+            log_time tx(eventData + 4 + 1);
+            if (ts != tx) {
+                if (0xDEADBEEFA55A5AA6ULL == caught_convert(eventData + 4 + 1)) {
+                    iters = i;
+                    break;
+                }
+                continue;
+            }
+
+            break;
+        }
+    }
+
+    signal(SIGALRM, SIG_DFL);
+    alarm(0);
+
+    StopBenchmarkTiming();
+
+    android_logger_list_free(logger_list);
+}
+BENCHMARK(BM_log_delay);