liblogcat: measure performance

Existing dummy benchmark converted to a single-pass benchmark.

Add support for ">[filename]" interpretation in liblogcat, helpful to
provide more consistent benchmark results when sending output to
/dev/null.

NB: results are not consistent as there is a roundtrip to logd
    service, but they are indicative of better performance for
    liblogcat.

Benchmark                                Time           CPU Iterations
----------------------------------------------------------------------
BM_logcat_stat_popen_libc         35221677 ns     603314 ns        100
BM_logcat_stat_popen_liblogcat    15871805 ns     579398 ns       1287
BM_logcat_stat_system_libc        39037825 ns     319882 ns        100
BM_logcat_stat_system_liblogcat    9896755 ns     762610 ns       1310
BM_logcat_dump_popen_libc        776206254 ns  131448772 ns          5
BM_logcat_dump_popen_liblogcat   610674905 ns  118709624 ns          6
BM_logcat_dump_system_libc       512191254 ns     388724 ns         10
BM_logcat_dump_system_liblogcat  443897570 ns  377215696 ns          2

Test: logcat-benchmarks --benchmark_filter='BM_logcat_stat*|BM_logcat_dump*'
Bug: 35326290
Change-Id: Ie94900a3070487f45742f6c0789b5b3cf036df34

3 files changed, 144 insertions, 41 deletions

diff --git a/logcat/tests/Android.mk b/logcat/tests/Android.mk
index 1c3febac3..22aca172a 100644
--- a/logcat/tests/Android.mk
+++ b/logcat/tests/Android.mk
@@ -27,11 +27,12 @@ test_c_flags := \
     -fno-builtin \
 
 # -----------------------------------------------------------------------------
-# Benchmarks (actually a gTest where the result code does not matter)
+# Benchmarks
 # ----------------------------------------------------------------------------
 
 benchmark_src_files := \
-    logcat_benchmark.cpp
+    logcat_benchmark.cpp \
+    exec_benchmark.cpp \
 
 # Build benchmarks for the device. Run with:
 #   adb shell /data/nativetest/logcat-benchmarks/logcat-benchmarks
@@ -40,7 +41,8 @@ LOCAL_MODULE := $(test_module_prefix)benchmarks
 LOCAL_MODULE_TAGS := $(test_tags)
 LOCAL_CFLAGS += $(test_c_flags)
 LOCAL_SRC_FILES := $(benchmark_src_files)
-include $(BUILD_NATIVE_TEST)
+LOCAL_SHARED_LIBRARIES := libbase liblogcat
+include $(BUILD_NATIVE_BENCHMARK)
 
 # -----------------------------------------------------------------------------
 # Unit tests.
diff --git a/logcat/tests/exec_benchmark.cpp b/logcat/tests/exec_benchmark.cpp
new file mode 100644
index 000000000..c30a5f5f1
--- /dev/null
+++ b/logcat/tests/exec_benchmark.cpp
@@ -0,0 +1,96 @@
+/*
+ * Copyright (C) 2017 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 <stdio.h>
+
+#include <android-base/file.h>
+#include <benchmark/benchmark.h>
+#include <log/logcat.h>
+
+// Dump the statistics and report results
+
+static void logcat_popen_libc(benchmark::State& state, const char* cmd) {
+    while (state.KeepRunning()) {
+        FILE* fp = popen(cmd, "r");
+        std::string ret;
+        android::base::ReadFdToString(fileno(fp), &ret);
+        pclose(fp);
+    }
+}
+
+static void BM_logcat_stat_popen_libc(benchmark::State& state) {
+    logcat_popen_libc(state, "logcat -b all -S");
+}
+BENCHMARK(BM_logcat_stat_popen_libc);
+
+static void logcat_popen_liblogcat(benchmark::State& state, const char* cmd) {
+    while (state.KeepRunning()) {
+        android_logcat_context ctx;
+        FILE* fp = android_logcat_popen(&ctx, cmd);
+        std::string ret;
+        android::base::ReadFdToString(fileno(fp), &ret);
+        android_logcat_pclose(&ctx, fp);
+    }
+}
+
+static void BM_logcat_stat_popen_liblogcat(benchmark::State& state) {
+    logcat_popen_liblogcat(state, "logcat -b all -S");
+}
+BENCHMARK(BM_logcat_stat_popen_liblogcat);
+
+static void logcat_system_libc(benchmark::State& state, const char* cmd) {
+    while (state.KeepRunning()) {
+        system(cmd);
+    }
+}
+
+static void BM_logcat_stat_system_libc(benchmark::State& state) {
+    logcat_system_libc(state, "logcat -b all -S >/dev/null 2>/dev/null");
+}
+BENCHMARK(BM_logcat_stat_system_libc);
+
+static void logcat_system_liblogcat(benchmark::State& state, const char* cmd) {
+    while (state.KeepRunning()) {
+        android_logcat_system(cmd);
+    }
+}
+
+static void BM_logcat_stat_system_liblogcat(benchmark::State& state) {
+    logcat_system_liblogcat(state, "logcat -b all -S >/dev/null 2>/dev/null");
+}
+BENCHMARK(BM_logcat_stat_system_liblogcat);
+
+// Dump the logs and report results
+
+static void BM_logcat_dump_popen_libc(benchmark::State& state) {
+    logcat_popen_libc(state, "logcat -b all -d");
+}
+BENCHMARK(BM_logcat_dump_popen_libc);
+
+static void BM_logcat_dump_popen_liblogcat(benchmark::State& state) {
+    logcat_popen_liblogcat(state, "logcat -b all -d");
+}
+BENCHMARK(BM_logcat_dump_popen_liblogcat);
+
+static void BM_logcat_dump_system_libc(benchmark::State& state) {
+    logcat_system_libc(state, "logcat -b all -d >/dev/null 2>/dev/null");
+}
+BENCHMARK(BM_logcat_dump_system_libc);
+
+static void BM_logcat_dump_system_liblogcat(benchmark::State& state) {
+    logcat_system_liblogcat(state, "logcat -b all -d >/dev/null 2>/dev/null");
+}
+BENCHMARK(BM_logcat_dump_system_liblogcat);
diff --git a/logcat/tests/logcat_benchmark.cpp b/logcat/tests/logcat_benchmark.cpp
index dd851643c..8d8862889 100644
--- a/logcat/tests/logcat_benchmark.cpp
+++ b/logcat/tests/logcat_benchmark.cpp
@@ -18,19 +18,22 @@
 #include <stdlib.h>
 #include <string.h>
 
-#include <gtest/gtest.h>
+#include <benchmark/benchmark.h>
 
 static const char begin[] = "--------- beginning of ";
 
-TEST(logcat, sorted_order) {
-    FILE *fp;
+static void BM_logcat_sorted_order(benchmark::State& state) {
+    FILE* fp;
 
-    ASSERT_TRUE(NULL != (fp = popen(
-      "logcat -v time -b radio -b events -b system -b main -d 2>/dev/null",
-      "r")));
+    if (!state.KeepRunning()) return;
+
+    fp = popen(
+        "logcat -v time -b radio -b events -b system -b main -d 2>/dev/null",
+        "r");
+    if (!fp) return;
 
     class timestamp {
-    private:
+       private:
         int month;
         int day;
         int hour;
@@ -39,44 +42,39 @@ TEST(logcat, sorted_order) {
         int millisecond;
         bool ok;
 
-    public:
-        void init(const char *buffer)
-        {
+       public:
+        void init(const char* buffer) {
             ok = false;
             if (buffer != NULL) {
-                ok = sscanf(buffer, "%d-%d %d:%d:%d.%d ",
-                    &month, &day, &hour, &minute, &second, &millisecond) == 6;
+                ok = sscanf(buffer, "%d-%d %d:%d:%d.%d ", &month, &day, &hour,
+                            &minute, &second, &millisecond) == 6;
             }
         }
 
-        explicit timestamp(const char *buffer)
-        {
+        explicit timestamp(const char* buffer) {
             init(buffer);
         }
 
-        bool operator< (timestamp &T)
-        {
-            return !ok || !T.ok
-             || (month < T.month)
-             || ((month == T.month)
-              && ((day < T.day)
-               || ((day == T.day)
-                && ((hour < T.hour)
-                 || ((hour == T.hour)
-                  && ((minute < T.minute)
-                   || ((minute == T.minute)
-                    && ((second < T.second)
-                     || ((second == T.second)
-                      && (millisecond < T.millisecond))))))))));
+        bool operator<(timestamp& T) {
+            return !ok || !T.ok || (month < T.month) ||
+                   ((month == T.month) &&
+                    ((day < T.day) ||
+                     ((day == T.day) &&
+                      ((hour < T.hour) ||
+                       ((hour == T.hour) &&
+                        ((minute < T.minute) ||
+                         ((minute == T.minute) &&
+                          ((second < T.second) ||
+                           ((second == T.second) &&
+                            (millisecond < T.millisecond))))))))));
         }
 
-        bool valid(void)
-        {
+        bool valid(void) {
             return ok;
         }
     } last(NULL);
 
-    char *last_buffer = NULL;
+    char* last_buffer = NULL;
     char buffer[5120];
 
     int count = 0;
@@ -114,15 +112,22 @@ TEST(logcat, sorted_order) {
 
     // Allow few fails, happens with readers active
     fprintf(stderr, "%s: %d/%d out of order entries\n",
-            (next_lt_last)
-                ? ((next_lt_last <= max_ok)
-                    ? "WARNING"
-                    : "ERROR")
-                : "INFO",
+            (next_lt_last) ? ((next_lt_last <= max_ok) ? "WARNING" : "ERROR")
+                           : "INFO",
             next_lt_last, count);
 
-    EXPECT_GE(max_ok, next_lt_last);
+    if (next_lt_last > max_ok) {
+        fprintf(stderr, "EXPECT_GE(max_ok=%d, next_lt_last=%d)\n", max_ok,
+                next_lt_last);
+    }
 
     // sample statistically too small
-    EXPECT_LT(100, count);
+    if (count < 100) {
+        fprintf(stderr, "EXPECT_LT(100, count=%d)\n", count);
+    }
+
+    state.KeepRunning();
 }
+BENCHMARK(BM_logcat_sorted_order);
+
+BENCHMARK_MAIN();