openkylin
/
platform_system_core
mirror of https://gitee.com/openkylin/platform_system_core.git
9
0
Fork 0
Code Issues Projects Releases Wiki Activity

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
This commit is contained in:
Mark Salyzyn 2018-01-11 11:20:24 -08:00
parent 3b44d2846e
commit 1520bd43b0
4 changed files with 133 additions and 556 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

7
liblog/tests/Android.mk
View File

@ -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.

147
liblog/tests/benchmark.h
View File

@ -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 <stdint.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <vector>
#ifndef BIONIC_BENCHMARK_H_
#define BIONIC_BENCHMARK_H_
namespace testing {
class Benchmark;
template <typename T> class BenchmarkWantsArg;
template <typename T> 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 <typename T>
class BenchmarkWantsArgBase : public Benchmark {
public:
BenchmarkWantsArgBase(const char* name, void (*fn)(int, T)) : Benchmark(name) {
fn_arg_ = fn;
}
BenchmarkWantsArgBase<T>* Arg(const char* arg_name, T arg) {
BenchmarkRegister(new BenchmarkWithArg<T>(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 <typename T>
class BenchmarkWithArg : public BenchmarkWantsArg<T> {
public:
BenchmarkWithArg(const char* name, void (*fn)(int, T), const char* arg_name, T arg) :
BenchmarkWantsArg<T>(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<T>::fn_arg_(iterations, arg_); }
private:
T arg_;
char* arg_name_;
};
template <typename T>
class BenchmarkWantsArg : public BenchmarkWantsArgBase<T> {
public:
BenchmarkWantsArg<T>(const char* name, void (*fn)(int, T)) :
BenchmarkWantsArgBase<T>(name, fn) { }
};
template <>
class BenchmarkWantsArg<int> : public BenchmarkWantsArgBase<int> {
public:
BenchmarkWantsArg<int>(const char* name, void (*fn)(int, int)) :
BenchmarkWantsArgBase<int>(name, fn) { }
BenchmarkWantsArg<int>* Arg(int arg) {
char arg_name[100];
PrettyPrintInt(arg_name, sizeof(arg_name), arg);
BenchmarkRegister(new BenchmarkWithArg<int>(name_, fn_arg_, arg_name, arg));
return this;
}
};
static inline Benchmark* BenchmarkFactory(const char* name, void (*fn)(int)) {
return new Benchmark(name, fn);
}
template <typename T>
static inline BenchmarkWantsArg<T>* BenchmarkFactory(const char* name, void (*fn)(int, T)) {
return new BenchmarkWantsArg<T>(name, fn);
}
} // namespace testing
template <typename T>
static inline void BenchmarkAddArg(::testing::Benchmark* b, const char* name, T arg) {
::testing::BenchmarkWantsArg<T>* ba;
ba = static_cast< ::testing::BenchmarkWantsArg<T>* >(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_

247
liblog/tests/benchmark_main.cpp
View File

@ -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 <benchmark.h>
#include <inttypes.h>
#include <math.h>
#include <regex.h>
#include <stdio.h>
#include <stdlib.h>
#include <map>
#include <string>
#include <vector>
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<uint64_t>(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<double>(gBytesProcessed) / 1e6;
double seconds = static_cast<double>(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<uint64_t>(iterations), mean, throughput);
} else {
printf("%-25s %10" PRIu64 " %10" PRIu64 "(\317\203%" PRIu64 ")%s\n",
full_name, static_cast<uint64_t>(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;
}

288
liblog/tests/liblog_benchmark.cpp
View File

@ -25,12 +25,13 @@
#include <unordered_set>
#include <android-base/file.h>
#include <benchmark/benchmark.h>
#include <cutils/sockets.h>
#include <log/event_tag_map.h>
#include <log/log_transport.h>
#include <private/android_logger.h>
#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<uint32_t>::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<uint32_t>::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<uint32_t>::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<uint32_t>::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();
}