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
diff --git a/logcat/tests/Android.mk b/logcat/tests/Android.mk
index 1c3feba..22aca17 100644
--- a/logcat/tests/Android.mk
+++ b/logcat/tests/Android.mk
@@ -27,11 +27,12 @@
-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_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 0000000..c30a5f5
--- /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 dd85164..8d88628 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 @@
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 @@
// 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();