From 1520bd43b0ce6511cd086eaf495692c4bc2f6d6b Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Thu, 11 Jan 2018 11:20:24 -0800 Subject: [PATCH] liblog: benchmarks use google-benchmark library Remove our circa 2014 snapshot of the google benchmarking library, and use the now very stable google-benchmark suite. Some porting effort, and deal with some benchmarking saddle points that take too long to sort out. Focus on minimal API changes, _odd_ new behaviors, and style. Test: liblog_benchmarks, ensure results in about the same range Bug: 69423514 Change-Id: I2add1df9cb664333bcf983b57121ae151b26935b --- liblog/tests/Android.mk | 7 +- liblog/tests/benchmark.h | 147 --------------- liblog/tests/benchmark_main.cpp | 247 ------------------------- liblog/tests/liblog_benchmark.cpp | 288 ++++++++++++++---------------- 4 files changed, 133 insertions(+), 556 deletions(-) delete mode 100644 liblog/tests/benchmark.h delete mode 100644 liblog/tests/benchmark_main.cpp diff --git a/liblog/tests/Android.mk b/liblog/tests/Android.mk index 39b52ac35..cfa849ba4 100644 --- a/liblog/tests/Android.mk +++ b/liblog/tests/Android.mk @@ -24,13 +24,12 @@ test_module_prefix := liblog- test_tags := tests benchmark_c_flags := \ - -Ibionic/tests \ - -Wall -Wextra \ + -Wall \ + -Wextra \ -Werror \ -fno-builtin \ benchmark_src_files := \ - benchmark_main.cpp \ liblog_benchmark.cpp # Build benchmarks for the device. Run with: @@ -41,7 +40,7 @@ LOCAL_MODULE_TAGS := $(test_tags) LOCAL_CFLAGS += $(benchmark_c_flags) LOCAL_SHARED_LIBRARIES += liblog libm libbase LOCAL_SRC_FILES := $(benchmark_src_files) -include $(BUILD_NATIVE_TEST) +include $(BUILD_NATIVE_BENCHMARK) # ----------------------------------------------------------------------------- # Unit tests. diff --git a/liblog/tests/benchmark.h b/liblog/tests/benchmark.h deleted file mode 100644 index e9280f63e..000000000 --- a/liblog/tests/benchmark.h +++ /dev/null @@ -1,147 +0,0 @@ -/* - * Copyright (C) 2012-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 -#include -#include -#include - -#include - -#ifndef BIONIC_BENCHMARK_H_ -#define BIONIC_BENCHMARK_H_ - -namespace testing { - -class Benchmark; -template class BenchmarkWantsArg; -template class BenchmarkWithArg; - -void BenchmarkRegister(Benchmark* bm); -int PrettyPrintInt(char* str, int len, unsigned int arg); - -class Benchmark { - public: - Benchmark(const char* name, void (*fn)(int)) : name_(strdup(name)), fn_(fn) { - BenchmarkRegister(this); - } - explicit Benchmark(const char* name) : name_(strdup(name)), fn_(NULL) {} - - virtual ~Benchmark() { - free(name_); - } - - const char* Name() { return name_; } - virtual const char* ArgName() { return NULL; } - virtual void RunFn(int iterations) { fn_(iterations); } - - protected: - char* name_; - - private: - void (*fn_)(int); -}; - -template -class BenchmarkWantsArgBase : public Benchmark { - public: - BenchmarkWantsArgBase(const char* name, void (*fn)(int, T)) : Benchmark(name) { - fn_arg_ = fn; - } - - BenchmarkWantsArgBase* Arg(const char* arg_name, T arg) { - BenchmarkRegister(new BenchmarkWithArg(name_, fn_arg_, arg_name, arg)); - return this; - } - - protected: - virtual void RunFn(int) { printf("can't run arg benchmark %s without arg\n", Name()); } - void (*fn_arg_)(int, T); -}; - -template -class BenchmarkWithArg : public BenchmarkWantsArg { - public: - BenchmarkWithArg(const char* name, void (*fn)(int, T), const char* arg_name, T arg) : - BenchmarkWantsArg(name, fn), arg_(arg) { - arg_name_ = strdup(arg_name); - } - - virtual ~BenchmarkWithArg() { - free(arg_name_); - } - - virtual const char* ArgName() { return arg_name_; } - - protected: - virtual void RunFn(int iterations) { BenchmarkWantsArg::fn_arg_(iterations, arg_); } - - private: - T arg_; - char* arg_name_; -}; - -template -class BenchmarkWantsArg : public BenchmarkWantsArgBase { - public: - BenchmarkWantsArg(const char* name, void (*fn)(int, T)) : - BenchmarkWantsArgBase(name, fn) { } -}; - -template <> -class BenchmarkWantsArg : public BenchmarkWantsArgBase { - public: - BenchmarkWantsArg(const char* name, void (*fn)(int, int)) : - BenchmarkWantsArgBase(name, fn) { } - - BenchmarkWantsArg* Arg(int arg) { - char arg_name[100]; - PrettyPrintInt(arg_name, sizeof(arg_name), arg); - BenchmarkRegister(new BenchmarkWithArg(name_, fn_arg_, arg_name, arg)); - return this; - } -}; - -static inline Benchmark* BenchmarkFactory(const char* name, void (*fn)(int)) { - return new Benchmark(name, fn); -} - -template -static inline BenchmarkWantsArg* BenchmarkFactory(const char* name, void (*fn)(int, T)) { - return new BenchmarkWantsArg(name, fn); -} - -} // namespace testing - -template -static inline void BenchmarkAddArg(::testing::Benchmark* b, const char* name, T arg) { - ::testing::BenchmarkWantsArg* ba; - ba = static_cast< ::testing::BenchmarkWantsArg* >(b); - ba->Arg(name, arg); -} - -void SetBenchmarkBytesProcessed(uint64_t); -void ResetBenchmarkTiming(void); -void StopBenchmarkTiming(void); -void StartBenchmarkTiming(void); -void StartBenchmarkTiming(uint64_t); -void StopBenchmarkTiming(uint64_t); - -#define BENCHMARK(f) \ - static ::testing::Benchmark* _benchmark_##f __attribute__((unused)) = /* NOLINT */ \ - (::testing::Benchmark*)::testing::BenchmarkFactory(#f, f) /* NOLINT */ - -#endif // BIONIC_BENCHMARK_H_ diff --git a/liblog/tests/benchmark_main.cpp b/liblog/tests/benchmark_main.cpp deleted file mode 100644 index 7367f1b52..000000000 --- a/liblog/tests/benchmark_main.cpp +++ /dev/null @@ -1,247 +0,0 @@ -/* - * Copyright (C) 2012-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 - -#include -#include -#include -#include -#include - -#include -#include -#include - -static uint64_t gBytesProcessed; -static uint64_t gBenchmarkTotalTimeNs; -static uint64_t gBenchmarkTotalTimeNsSquared; -static uint64_t gBenchmarkNum; -static uint64_t gBenchmarkStartTimeNs; - -typedef std::vector< ::testing::Benchmark*> BenchmarkList; -static BenchmarkList* gBenchmarks; - -static int Round(int n) { - int base = 1; - while (base * 10 < n) { - base *= 10; - } - if (n < 2 * base) { - return 2 * base; - } - if (n < 5 * base) { - return 5 * base; - } - return 10 * base; -} - -static uint64_t NanoTime() { - struct timespec t; - t.tv_sec = t.tv_nsec = 0; - clock_gettime(CLOCK_MONOTONIC, &t); - return static_cast(t.tv_sec) * 1000000000ULL + t.tv_nsec; -} - -namespace testing { - -int PrettyPrintInt(char* str, int len, unsigned int arg) { - if (arg >= (1 << 30) && arg % (1 << 30) == 0) { - return snprintf(str, len, "%uGi", arg / (1 << 30)); - } else if (arg >= (1 << 20) && arg % (1 << 20) == 0) { - return snprintf(str, len, "%uMi", arg / (1 << 20)); - } else if (arg >= (1 << 10) && arg % (1 << 10) == 0) { - return snprintf(str, len, "%uKi", arg / (1 << 10)); - } else if (arg >= 1000000000 && arg % 1000000000 == 0) { - return snprintf(str, len, "%uG", arg / 1000000000); - } else if (arg >= 1000000 && arg % 1000000 == 0) { - return snprintf(str, len, "%uM", arg / 1000000); - } else if (arg >= 1000 && arg % 1000 == 0) { - return snprintf(str, len, "%uK", arg / 1000); - } else { - return snprintf(str, len, "%u", arg); - } -} - -bool ShouldRun(Benchmark* b, int argc, char* argv[]) { - if (argc == 1) { - return true; // With no arguments, we run all benchmarks. - } - // Otherwise, we interpret each argument as a regular expression and - // see if any of our benchmarks match. - for (int i = 1; i < argc; i++) { - regex_t re; - if (regcomp(&re, argv[i], 0) != 0) { - fprintf(stderr, "couldn't compile \"%s\" as a regular expression!\n", - argv[i]); - exit(EXIT_FAILURE); - } - int match = regexec(&re, b->Name(), 0, NULL, 0); - regfree(&re); - if (match != REG_NOMATCH) { - return true; - } - } - return false; -} - -void BenchmarkRegister(Benchmark* b) { - if (gBenchmarks == NULL) { - gBenchmarks = new BenchmarkList; - } - gBenchmarks->push_back(b); -} - -void RunRepeatedly(Benchmark* b, int iterations) { - gBytesProcessed = 0; - ResetBenchmarkTiming(); - uint64_t StartTimeNs = NanoTime(); - b->RunFn(iterations); - // Catch us if we fail to log anything. - if ((gBenchmarkTotalTimeNs == 0) && (StartTimeNs != 0) && - (gBenchmarkStartTimeNs == 0)) { - gBenchmarkTotalTimeNs = NanoTime() - StartTimeNs; - } -} - -void Run(Benchmark* b) { - // run once in case it's expensive - unsigned iterations = 1; - uint64_t s = NanoTime(); - RunRepeatedly(b, iterations); - s = NanoTime() - s; - while (s < 2e9 && gBenchmarkTotalTimeNs < 1e9 && iterations < 1e9) { - unsigned last = iterations; - if (gBenchmarkTotalTimeNs / iterations == 0) { - iterations = 1e9; - } else { - iterations = 1e9 / (gBenchmarkTotalTimeNs / iterations); - } - iterations = - std::max(last + 1, std::min(iterations + iterations / 2, 100 * last)); - iterations = Round(iterations); - s = NanoTime(); - RunRepeatedly(b, iterations); - s = NanoTime() - s; - } - - char throughput[100]; - throughput[0] = '\0'; - if (gBenchmarkTotalTimeNs > 0 && gBytesProcessed > 0) { - double mib_processed = static_cast(gBytesProcessed) / 1e6; - double seconds = static_cast(gBenchmarkTotalTimeNs) / 1e9; - snprintf(throughput, sizeof(throughput), " %8.2f MiB/s", - mib_processed / seconds); - } - - char full_name[100]; - snprintf(full_name, sizeof(full_name), "%s%s%s", b->Name(), - b->ArgName() ? "/" : "", b->ArgName() ? b->ArgName() : ""); - - uint64_t mean = gBenchmarkTotalTimeNs / iterations; - uint64_t sdev = 0; - if (gBenchmarkNum == iterations) { - mean = gBenchmarkTotalTimeNs / gBenchmarkNum; - uint64_t nXvariance = gBenchmarkTotalTimeNsSquared * gBenchmarkNum - - (gBenchmarkTotalTimeNs * gBenchmarkTotalTimeNs); - sdev = (sqrt((double)nXvariance) / gBenchmarkNum / gBenchmarkNum) + 0.5; - } - if (mean > (10000 * sdev)) { - printf("%-25s %10" PRIu64 " %10" PRIu64 "%s\n", full_name, - static_cast(iterations), mean, throughput); - } else { - printf("%-25s %10" PRIu64 " %10" PRIu64 "(\317\203%" PRIu64 ")%s\n", - full_name, static_cast(iterations), mean, sdev, throughput); - } - fflush(stdout); -} - -} // namespace testing - -void SetBenchmarkBytesProcessed(uint64_t x) { - gBytesProcessed = x; -} - -void ResetBenchmarkTiming() { - gBenchmarkStartTimeNs = 0; - gBenchmarkTotalTimeNs = 0; - gBenchmarkTotalTimeNsSquared = 0; - gBenchmarkNum = 0; -} - -void StopBenchmarkTiming(void) { - if (gBenchmarkStartTimeNs != 0) { - int64_t diff = NanoTime() - gBenchmarkStartTimeNs; - gBenchmarkTotalTimeNs += diff; - gBenchmarkTotalTimeNsSquared += diff * diff; - ++gBenchmarkNum; - } - gBenchmarkStartTimeNs = 0; -} - -void StartBenchmarkTiming(void) { - if (gBenchmarkStartTimeNs == 0) { - gBenchmarkStartTimeNs = NanoTime(); - } -} - -void StopBenchmarkTiming(uint64_t NanoTime) { - if (gBenchmarkStartTimeNs != 0) { - int64_t diff = NanoTime - gBenchmarkStartTimeNs; - gBenchmarkTotalTimeNs += diff; - gBenchmarkTotalTimeNsSquared += diff * diff; - if (NanoTime != 0) { - ++gBenchmarkNum; - } - } - gBenchmarkStartTimeNs = 0; -} - -void StartBenchmarkTiming(uint64_t NanoTime) { - if (gBenchmarkStartTimeNs == 0) { - gBenchmarkStartTimeNs = NanoTime; - } -} - -int main(int argc, char* argv[]) { - if (gBenchmarks->empty()) { - fprintf(stderr, "No benchmarks registered!\n"); - exit(EXIT_FAILURE); - } - - bool need_header = true; - for (auto b : *gBenchmarks) { - if (ShouldRun(b, argc, argv)) { - if (need_header) { - printf("%-25s %10s %10s\n", "", "iterations", "ns/op"); - fflush(stdout); - need_header = false; - } - Run(b); - } - } - - if (need_header) { - fprintf(stderr, "No matching benchmarks!\n"); - fprintf(stderr, "Available benchmarks:\n"); - for (auto b : *gBenchmarks) { - fprintf(stderr, " %s\n", b->Name()); - } - exit(EXIT_FAILURE); - } - - return 0; -} diff --git a/liblog/tests/liblog_benchmark.cpp b/liblog/tests/liblog_benchmark.cpp index c4bf95962..706a0f6ae 100644 --- a/liblog/tests/liblog_benchmark.cpp +++ b/liblog/tests/liblog_benchmark.cpp @@ -25,12 +25,13 @@ #include #include +#include #include #include #include #include -#include "benchmark.h" +BENCHMARK_MAIN(); // 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 @@ -51,15 +52,11 @@ * 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)); +static void BM_log_maximum_retry(benchmark::State& state) { + while (state.KeepRunning()) { + LOG_FAILURE_RETRY(__android_log_print( + ANDROID_LOG_INFO, "BM_log_maximum_retry", "%zu", state.iterations())); } - - StopBenchmarkTiming(); } BENCHMARK(BM_log_maximum_retry); @@ -68,14 +65,11 @@ BENCHMARK(BM_log_maximum_retry); * 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); +static void BM_log_maximum(benchmark::State& state) { + while (state.KeepRunning()) { + __android_log_print(ANDROID_LOG_INFO, "BM_log_maximum", "%zu", + state.iterations()); } - - StopBenchmarkTiming(); } BENCHMARK(BM_log_maximum); @@ -87,26 +81,28 @@ static void set_log_default() { android_set_log_transport(LOGGER_DEFAULT); } -static void BM_log_maximum_null(int iters) { +static void BM_log_maximum_null(benchmark::State& state) { set_log_null(); - BM_log_maximum(iters); + BM_log_maximum(state); set_log_default(); } BENCHMARK(BM_log_maximum_null); /* * Measure the time it takes to collect the time using - * discrete acquisition (StartBenchmarkTiming() -> StopBenchmarkTiming()) + * discrete acquisition (state.PauseTiming() to state.ResumeTiming()) * under light load. Expect this to be a syscall period (2us) or * data read time if zero-syscall. * * vdso support in the kernel and the library can allow - * clock_gettime to be zero-syscall. + * clock_gettime to be zero-syscall, but there there does remain some + * benchmarking overhead to pause and resume; assumptions are both are + * covered. */ -static void BM_clock_overhead(int iters) { - for (int i = 0; i < iters; ++i) { - StartBenchmarkTiming(); - StopBenchmarkTiming(); +static void BM_clock_overhead(benchmark::State& state) { + while (state.KeepRunning()) { + state.PauseTiming(); + state.ResumeTiming(); } } BENCHMARK(BM_clock_overhead); @@ -114,9 +110,10 @@ BENCHMARK(BM_clock_overhead); /* * Measure the time it takes to submit the android logging data to pstore */ -static void BM_pmsg_short(int iters) { +static void BM_pmsg_short(benchmark::State& state) { int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY)); if (pstore_fd < 0) { + state.SkipWithError("/dev/pmsg0"); return; } @@ -175,13 +172,12 @@ static void BM_pmsg_short(int iters) { newVec[2].iov_base = &buffer; newVec[2].iov_len = sizeof(buffer); - StartBenchmarkTiming(); - for (int i = 0; i < iters; ++i) { + while (state.KeepRunning()) { ++snapshot; buffer.payload.data = htole32(snapshot); writev(pstore_fd, newVec, nr); } - StopBenchmarkTiming(); + state.PauseTiming(); close(pstore_fd); } BENCHMARK(BM_pmsg_short); @@ -190,9 +186,10 @@ BENCHMARK(BM_pmsg_short); * Measure the time it takes to submit the android logging data to pstore * best case aligned single block. */ -static void BM_pmsg_short_aligned(int iters) { +static void BM_pmsg_short_aligned(benchmark::State& state) { int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY)); if (pstore_fd < 0) { + state.SkipWithError("/dev/pmsg0"); return; } @@ -228,7 +225,8 @@ static void BM_pmsg_short_aligned(int iters) { memset(buf, 0, sizeof(buf)); struct packet* buffer = (struct packet*)(((uintptr_t)buf + 7) & ~7); if (((uintptr_t)&buffer->pmsg_header) & 7) { - fprintf(stderr, "&buffer=0x%p iters=%d\n", &buffer->pmsg_header, iters); + fprintf(stderr, "&buffer=0x%p iterations=%zu\n", &buffer->pmsg_header, + state.iterations()); } buffer->pmsg_header.magic = LOGGER_MAGIC; @@ -247,15 +245,14 @@ static void BM_pmsg_short_aligned(int iters) { uint32_t snapshot = 0; buffer->payload.payload.data = htole32(snapshot); - StartBenchmarkTiming(); - for (int i = 0; i < iters; ++i) { + while (state.KeepRunning()) { ++snapshot; buffer->payload.payload.data = htole32(snapshot); write(pstore_fd, &buffer->pmsg_header, sizeof(android_pmsg_log_header_t) + sizeof(android_log_header_t) + sizeof(android_log_event_int_t)); } - StopBenchmarkTiming(); + state.PauseTiming(); close(pstore_fd); } BENCHMARK(BM_pmsg_short_aligned); @@ -264,9 +261,10 @@ BENCHMARK(BM_pmsg_short_aligned); * Measure the time it takes to submit the android logging data to pstore * best case aligned single block. */ -static void BM_pmsg_short_unaligned1(int iters) { +static void BM_pmsg_short_unaligned1(benchmark::State& state) { int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY)); if (pstore_fd < 0) { + state.SkipWithError("/dev/pmsg0"); return; } @@ -302,7 +300,8 @@ static void BM_pmsg_short_unaligned1(int iters) { memset(buf, 0, sizeof(buf)); struct packet* buffer = (struct packet*)((((uintptr_t)buf + 7) & ~7) + 1); if ((((uintptr_t)&buffer->pmsg_header) & 7) != 1) { - fprintf(stderr, "&buffer=0x%p iters=%d\n", &buffer->pmsg_header, iters); + fprintf(stderr, "&buffer=0x%p iterations=%zu\n", &buffer->pmsg_header, + state.iterations()); } buffer->pmsg_header.magic = LOGGER_MAGIC; @@ -321,15 +320,14 @@ static void BM_pmsg_short_unaligned1(int iters) { uint32_t snapshot = 0; buffer->payload.payload.data = htole32(snapshot); - StartBenchmarkTiming(); - for (int i = 0; i < iters; ++i) { + while (state.KeepRunning()) { ++snapshot; buffer->payload.payload.data = htole32(snapshot); write(pstore_fd, &buffer->pmsg_header, sizeof(android_pmsg_log_header_t) + sizeof(android_log_header_t) + sizeof(android_log_event_int_t)); } - StopBenchmarkTiming(); + state.PauseTiming(); close(pstore_fd); } BENCHMARK(BM_pmsg_short_unaligned1); @@ -338,9 +336,10 @@ BENCHMARK(BM_pmsg_short_unaligned1); * Measure the time it takes to submit the android logging data to pstore * best case aligned single block. */ -static void BM_pmsg_long_aligned(int iters) { +static void BM_pmsg_long_aligned(benchmark::State& state) { int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY)); if (pstore_fd < 0) { + state.SkipWithError("/dev/pmsg0"); return; } @@ -376,7 +375,8 @@ static void BM_pmsg_long_aligned(int iters) { memset(buf, 0, sizeof(buf)); struct packet* buffer = (struct packet*)(((uintptr_t)buf + 7) & ~7); if (((uintptr_t)&buffer->pmsg_header) & 7) { - fprintf(stderr, "&buffer=0x%p iters=%d\n", &buffer->pmsg_header, iters); + fprintf(stderr, "&buffer=0x%p iterations=%zu\n", &buffer->pmsg_header, + state.iterations()); } buffer->pmsg_header.magic = LOGGER_MAGIC; @@ -395,13 +395,12 @@ static void BM_pmsg_long_aligned(int iters) { uint32_t snapshot = 0; buffer->payload.payload.data = htole32(snapshot); - StartBenchmarkTiming(); - for (int i = 0; i < iters; ++i) { + while (state.KeepRunning()) { ++snapshot; buffer->payload.payload.data = htole32(snapshot); write(pstore_fd, &buffer->pmsg_header, LOGGER_ENTRY_MAX_PAYLOAD); } - StopBenchmarkTiming(); + state.PauseTiming(); close(pstore_fd); } BENCHMARK(BM_pmsg_long_aligned); @@ -410,9 +409,10 @@ BENCHMARK(BM_pmsg_long_aligned); * Measure the time it takes to submit the android logging data to pstore * best case aligned single block. */ -static void BM_pmsg_long_unaligned1(int iters) { +static void BM_pmsg_long_unaligned1(benchmark::State& state) { int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY)); if (pstore_fd < 0) { + state.SkipWithError("/dev/pmsg0"); return; } @@ -448,7 +448,8 @@ static void BM_pmsg_long_unaligned1(int iters) { memset(buf, 0, sizeof(buf)); struct packet* buffer = (struct packet*)((((uintptr_t)buf + 7) & ~7) + 1); if ((((uintptr_t)&buffer->pmsg_header) & 7) != 1) { - fprintf(stderr, "&buffer=0x%p iters=%d\n", &buffer->pmsg_header, iters); + fprintf(stderr, "&buffer=0x%p iterations=%zu\n", &buffer->pmsg_header, + state.iterations()); } buffer->pmsg_header.magic = LOGGER_MAGIC; @@ -467,22 +468,20 @@ static void BM_pmsg_long_unaligned1(int iters) { uint32_t snapshot = 0; buffer->payload.payload.data = htole32(snapshot); - StartBenchmarkTiming(); - for (int i = 0; i < iters; ++i) { + while (state.KeepRunning()) { ++snapshot; buffer->payload.payload.data = htole32(snapshot); write(pstore_fd, &buffer->pmsg_header, LOGGER_ENTRY_MAX_PAYLOAD); } - StopBenchmarkTiming(); + state.PauseTiming(); close(pstore_fd); } BENCHMARK(BM_pmsg_long_unaligned1); /* * Measure the time it takes to form sprintf plus time using - * discrete acquisition (StartBenchmarkTiming() -> StopBenchmarkTiming()) - * under light load. Expect this to be a syscall period (2us) or sprintf - * time if zero-syscall time. + * discrete acquisition under light load. Expect this to be a syscall period + * (2us) or sprintf time if zero-syscall time. */ /* helper function */ static void test_print(const char* fmt, ...) { @@ -498,58 +497,55 @@ static void test_print(const char* fmt, ...) { #define logd_sleep() usleep(50) // really allow logd to catch up /* performance test */ -static void BM_sprintf_overhead(int iters) { - for (int i = 0; i < iters; ++i) { - StartBenchmarkTiming(); - test_print("BM_sprintf_overhead:%d", i); - StopBenchmarkTiming(); +static void BM_sprintf_overhead(benchmark::State& state) { + while (state.KeepRunning()) { + test_print("BM_sprintf_overhead:%zu", state.iterations()); + state.PauseTiming(); logd_yield(); + state.ResumeTiming(); } } BENCHMARK(BM_sprintf_overhead); /* * Measure the time it takes to submit the android printing logging call - * using discrete acquisition discrete acquisition (StartBenchmarkTiming() -> - * StopBenchmarkTiming()) under light load. Expect this to be a dozen or so - * syscall periods (40us) plus time to run *printf + * using discrete acquisition discrete acquisition under light load. Expect + * this to be a dozen or so syscall periods (40us) plus time to run *printf */ -static void BM_log_print_overhead(int iters) { - for (int i = 0; i < iters; ++i) { - StartBenchmarkTiming(); - __android_log_print(ANDROID_LOG_INFO, "BM_log_overhead", "%d", i); - StopBenchmarkTiming(); +static void BM_log_print_overhead(benchmark::State& state) { + while (state.KeepRunning()) { + __android_log_print(ANDROID_LOG_INFO, "BM_log_overhead", "%zu", + state.iterations()); + state.PauseTiming(); logd_yield(); + state.ResumeTiming(); } } BENCHMARK(BM_log_print_overhead); /* * Measure the time it takes to submit the android event logging call - * using discrete acquisition (StartBenchmarkTiming() -> StopBenchmarkTiming()) - * under light load. Expect this to be a long path to logger to convert the - * unknown tag (0) into a tagname (less than 200us). + * using discrete acquisition under light load. Expect this to be a long path + * to logger to convert the unknown tag (0) into a tagname (less than 200us). */ -static void BM_log_event_overhead(int iters) { - for (unsigned long long i = 0; i < (unsigned)iters; ++i) { - StartBenchmarkTiming(); +static void BM_log_event_overhead(benchmark::State& state) { + for (int64_t i = 0; state.KeepRunning(); ++i) { // log tag number 0 is not known, nor shall it ever be known __android_log_btwrite(0, EVENT_TYPE_LONG, &i, sizeof(i)); - StopBenchmarkTiming(); + state.PauseTiming(); logd_yield(); + state.ResumeTiming(); } } BENCHMARK(BM_log_event_overhead); /* * Measure the time it takes to submit the android event logging call - * using discrete acquisition (StartBenchmarkTiming() -> StopBenchmarkTiming()) - * under light load with a known logtag. Expect this to be a dozen or so - * syscall periods (less than 40us) + * using discrete acquisition under light load with a known logtag. Expect + * this to be a dozen or so syscall periods (less than 40us) */ -static void BM_log_event_overhead_42(int iters) { - for (unsigned long long i = 0; i < (unsigned)iters; ++i) { - StartBenchmarkTiming(); +static void BM_log_event_overhead_42(benchmark::State& state) { + for (int64_t i = 0; state.KeepRunning(); ++i) { // In system/core/logcat/event.logtags: // # These are used for testing, do not modify without updating // # tests/framework-tests/src/android/util/EventLogFunctionalTest.java. @@ -557,40 +553,42 @@ static void BM_log_event_overhead_42(int iters) { // # system/core/liblog/tests/liblog_test.cpp // 42 answer (to life the universe etc|3) __android_log_btwrite(42, EVENT_TYPE_LONG, &i, sizeof(i)); - StopBenchmarkTiming(); + state.PauseTiming(); logd_yield(); + state.ResumeTiming(); } } BENCHMARK(BM_log_event_overhead_42); -static void BM_log_event_overhead_null(int iters) { +static void BM_log_event_overhead_null(benchmark::State& state) { set_log_null(); - BM_log_event_overhead(iters); + BM_log_event_overhead(state); set_log_default(); } BENCHMARK(BM_log_event_overhead_null); /* * Measure the time it takes to submit the android event logging call - * using discrete acquisition (StartBenchmarkTiming() -> StopBenchmarkTiming()) - * under very-light load (<1% CPU utilization). + * using discrete acquisition under very-light load (<1% CPU utilization). */ -static void BM_log_light_overhead(int iters) { - for (unsigned long long i = 0; i < (unsigned)iters; ++i) { - StartBenchmarkTiming(); +static void BM_log_light_overhead(benchmark::State& state) { + for (int64_t i = 0; state.KeepRunning(); ++i) { __android_log_btwrite(0, EVENT_TYPE_LONG, &i, sizeof(i)); - StopBenchmarkTiming(); + state.PauseTiming(); usleep(10000); + state.ResumeTiming(); } } BENCHMARK(BM_log_light_overhead); -static void BM_log_light_overhead_null(int iters) { +static void BM_log_light_overhead_null(benchmark::State& state) { set_log_null(); - BM_log_light_overhead(iters); + BM_log_light_overhead(state); set_log_default(); } -BENCHMARK(BM_log_light_overhead_null); +// Default gets out of hand for this test, so we set a reasonable number of +// iterations for a timely result. +BENCHMARK(BM_log_light_overhead_null)->Iterations(500); static void caught_latency(int /*signum*/) { unsigned long long v = 0xDEADBEEFA55A5AA5ULL; @@ -614,10 +612,12 @@ 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). + * timestamp to place into the internal record. Expect this to be less than + * 4 syscalls (3us). This test uses manual injection of timing because it is + * comparing the timestamp at send, and then picking up the corresponding log + * end-to-end long path from logd to see what actual timestamp was submitted. */ -static void BM_log_latency(int iters) { +static void BM_log_latency(benchmark::State& state) { pid_t pid = getpid(); struct logger_list* logger_list = @@ -631,7 +631,8 @@ static void BM_log_latency(int iters) { signal(SIGALRM, caught_latency); alarm(alarm_time); - for (int j = 0, i = 0; i < iters && j < 10 * iters; ++i, ++j) { + for (size_t j = 0; state.KeepRunning() && j < 10 * state.iterations(); ++j) { + retry: // We allow transitory errors (logd overloaded) to be retried. log_time ts; LOG_FAILURE_RETRY((ts = log_time(CLOCK_REALTIME), android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts)))); @@ -642,7 +643,7 @@ static void BM_log_latency(int iters) { alarm(alarm_time); if (ret <= 0) { - iters = i; + state.SkipWithError("android_logger_list_read"); break; } if ((log_msg.entry.len != (4 + 1 + 8)) || @@ -658,7 +659,7 @@ static void BM_log_latency(int iters) { log_time tx(eventData + 4 + 1); if (ts != tx) { if (0xDEADBEEFA55A5AA5ULL == caught_convert(eventData + 4 + 1)) { - iters = i; + state.SkipWithError("signal"); break; } continue; @@ -666,12 +667,8 @@ static void BM_log_latency(int iters) { uint64_t start = ts.nsec(); uint64_t end = log_msg.nsec(); - if (end >= start) { - StartBenchmarkTiming(start); - StopBenchmarkTiming(end); - } else { - --i; - } + if (end < start) goto retry; + state.SetIterationTime((end - start) / (double)NS_PER_SEC); break; } } @@ -681,7 +678,9 @@ static void BM_log_latency(int iters) { android_logger_list_free(logger_list); } -BENCHMARK(BM_log_latency); +// Default gets out of hand for this test, so we set a reasonable number of +// iterations for a timely result. +BENCHMARK(BM_log_latency)->UseManualTime()->Iterations(200); static void caught_delay(int /*signum*/) { unsigned long long v = 0xDEADBEEFA55A5AA6ULL; @@ -693,7 +692,7 @@ static void caught_delay(int /*signum*/) { * 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) { +static void BM_log_delay(benchmark::State& state) { pid_t pid = getpid(); struct logger_list* logger_list = @@ -707,9 +706,7 @@ static void BM_log_delay(int iters) { signal(SIGALRM, caught_delay); alarm(alarm_time); - StartBenchmarkTiming(); - - for (int i = 0; i < iters; ++i) { + while (state.KeepRunning()) { log_time ts(CLOCK_REALTIME); LOG_FAILURE_RETRY(android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts))); @@ -720,7 +717,7 @@ static void BM_log_delay(int iters) { alarm(alarm_time); if (ret <= 0) { - iters = i; + state.SkipWithError("android_logger_list_read"); break; } if ((log_msg.entry.len != (4 + 1 + 8)) || @@ -736,7 +733,7 @@ static void BM_log_delay(int iters) { log_time tx(eventData + 4 + 1); if (ts != tx) { if (0xDEADBEEFA55A5AA6ULL == caught_convert(eventData + 4 + 1)) { - iters = i; + state.SkipWithError("signal"); break; } continue; @@ -745,12 +742,11 @@ static void BM_log_delay(int iters) { break; } } + state.PauseTiming(); signal(SIGALRM, SIG_DFL); alarm(0); - StopBenchmarkTiming(); - android_logger_list_free(logger_list); } BENCHMARK(BM_log_delay); @@ -758,45 +754,33 @@ BENCHMARK(BM_log_delay); /* * Measure the time it takes for __android_log_is_loggable. */ -static void BM_is_loggable(int iters) { +static void BM_is_loggable(benchmark::State& state) { static const char logd[] = "logd"; - StartBenchmarkTiming(); - - for (int i = 0; i < iters; ++i) { + while (state.KeepRunning()) { __android_log_is_loggable_len(ANDROID_LOG_WARN, logd, strlen(logd), ANDROID_LOG_VERBOSE); } - - StopBenchmarkTiming(); } BENCHMARK(BM_is_loggable); /* * Measure the time it takes for android_log_clockid. */ -static void BM_clockid(int iters) { - StartBenchmarkTiming(); - - for (int i = 0; i < iters; ++i) { +static void BM_clockid(benchmark::State& state) { + while (state.KeepRunning()) { android_log_clockid(); } - - StopBenchmarkTiming(); } BENCHMARK(BM_clockid); /* * Measure the time it takes for __android_log_security. */ -static void BM_security(int iters) { - StartBenchmarkTiming(); - - for (int i = 0; i < iters; ++i) { +static void BM_security(benchmark::State& state) { + while (state.KeepRunning()) { __android_log_security(); } - - StopBenchmarkTiming(); } BENCHMARK(BM_security); @@ -824,21 +808,17 @@ static bool prechargeEventMap() { /* * Measure the time it takes for android_lookupEventTag_len */ -static void BM_lookupEventTag(int iters) { +static void BM_lookupEventTag(benchmark::State& state) { prechargeEventMap(); std::unordered_set::const_iterator it = set.begin(); - StartBenchmarkTiming(); - - for (int i = 0; i < iters; ++i) { + while (state.KeepRunning()) { size_t len; android_lookupEventTag_len(map, &len, (*it)); ++it; if (it == set.end()) it = set.begin(); } - - StopBenchmarkTiming(); } BENCHMARK(BM_lookupEventTag); @@ -847,7 +827,7 @@ BENCHMARK(BM_lookupEventTag); */ static uint32_t notTag = 1; -static void BM_lookupEventTag_NOT(int iters) { +static void BM_lookupEventTag_NOT(benchmark::State& state) { prechargeEventMap(); while (set.find(notTag) != set.end()) { @@ -855,15 +835,11 @@ static void BM_lookupEventTag_NOT(int iters) { if (notTag >= USHRT_MAX) notTag = 1; } - StartBenchmarkTiming(); - - for (int i = 0; i < iters; ++i) { + while (state.KeepRunning()) { size_t len; android_lookupEventTag_len(map, &len, notTag); } - StopBenchmarkTiming(); - ++notTag; if (notTag >= USHRT_MAX) notTag = 1; } @@ -872,42 +848,38 @@ BENCHMARK(BM_lookupEventTag_NOT); /* * Measure the time it takes for android_lookupEventFormat_len */ -static void BM_lookupEventFormat(int iters) { +static void BM_lookupEventFormat(benchmark::State& state) { prechargeEventMap(); std::unordered_set::const_iterator it = set.begin(); - StartBenchmarkTiming(); - - for (int i = 0; i < iters; ++i) { + while (state.KeepRunning()) { size_t len; android_lookupEventFormat_len(map, &len, (*it)); ++it; if (it == set.end()) it = set.begin(); } - - StopBenchmarkTiming(); } BENCHMARK(BM_lookupEventFormat); /* * Measure the time it takes for android_lookupEventTagNum plus above */ -static void BM_lookupEventTagNum(int iters) { +static void BM_lookupEventTagNum(benchmark::State& state) { prechargeEventMap(); std::unordered_set::const_iterator it = set.begin(); - for (int i = 0; i < iters; ++i) { + while (state.KeepRunning()) { size_t len; const char* name = android_lookupEventTag_len(map, &len, (*it)); std::string Name(name, len); const char* format = android_lookupEventFormat_len(map, &len, (*it)); std::string Format(format, len); - StartBenchmarkTiming(); + state.ResumeTiming(); android_lookupEventTagNum(map, Name.c_str(), Format.c_str(), ANDROID_LOG_UNKNOWN); - StopBenchmarkTiming(); + state.PauseTiming(); ++it; if (it == set.end()) it = set.begin(); } @@ -943,7 +915,7 @@ static void send_to_control(char* buf, size_t len) { close(sock); } -static void BM_lookupEventTagNum_logd_new(int iters) { +static void BM_lookupEventTagNum_logd_new(benchmark::State& state) { fprintf(stderr, "WARNING: " "This test can cause logd to grow in size and hit DOS limiter\n"); @@ -965,7 +937,7 @@ static void BM_lookupEventTagNum_logd_new(int iters) { data_event_log_tags = empty_event_log_tags; } - for (int i = 0; i < iters; ++i) { + while (state.KeepRunning()) { char buffer[256]; memset(buffer, 0, sizeof(buffer)); log_time now(CLOCK_MONOTONIC); @@ -973,9 +945,9 @@ static void BM_lookupEventTagNum_logd_new(int iters) { snprintf(name, sizeof(name), "a%" PRIu64, now.nsec()); snprintf(buffer, sizeof(buffer), "getEventTag name=%s format=\"(new|1)\"", name); - StartBenchmarkTiming(); + state.ResumeTiming(); send_to_control(buffer, sizeof(buffer)); - StopBenchmarkTiming(); + state.PauseTiming(); } // Restore copies (logd still know about them, until crash or reboot) @@ -1002,12 +974,12 @@ static void BM_lookupEventTagNum_logd_new(int iters) { } BENCHMARK(BM_lookupEventTagNum_logd_new); -static void BM_lookupEventTagNum_logd_existing(int iters) { +static void BM_lookupEventTagNum_logd_existing(benchmark::State& state) { prechargeEventMap(); std::unordered_set::const_iterator it = set.begin(); - for (int i = 0; i < iters; ++i) { + while (state.KeepRunning()) { size_t len; const char* name = android_lookupEventTag_len(map, &len, (*it)); std::string Name(name, len); @@ -1018,9 +990,9 @@ static void BM_lookupEventTagNum_logd_existing(int iters) { snprintf(buffer, sizeof(buffer), "getEventTag name=%s format=\"%s\"", Name.c_str(), Format.c_str()); - StartBenchmarkTiming(); + state.ResumeTiming(); send_to_control(buffer, sizeof(buffer)); - StopBenchmarkTiming(); + state.PauseTiming(); ++it; if (it == set.end()) it = set.begin(); }